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

Application Startup Broken (Doesnt Start) #8623

Closed
bryanhunwardsen opened this issue Oct 26, 2020 · 5 comments
Closed

Application Startup Broken (Doesnt Start) #8623

bryanhunwardsen opened this issue Oct 26, 2020 · 5 comments
Labels
Type: Bug The code does not produce the intended behavior.

Comments

@bryanhunwardsen
Copy link

Application version
4.7.0 & 4.7.1 (at least)

Platform
Windows 10 2004 and Insider 10.0.20241.1005

Printer
(Custom) Ender3V2

Reproduction steps
(Multiple Independent machines/installations all affected)

  1. Start Cura early last week (Loads at its normal slow speed but it loads)
  2. Start Cura late last week Cura startup hangs on loading settings (still at small splash screen)
    2.1) Click on splash screen, windows reports Cura.exe not responding, begins windows crash flow.
    2.2) Chask task manager for cura.exe process/ram/network/file system images, no indication of issue all values very low for exe and system
    2.3) Check log file, no errors in the tail to indicate the issue, few warnings about inability to load unnamed plugin.
    2.4) Force close process
    2.5 repeat several times, no change in behavior across reboots, task kills, upgrade to 4.7.1, etc
    As I had not changed anything my expectation was that some remote/network integration is failing, or a settings config was corrupted and Cura hangs unable to log and recover from such failure.

I tried 4 days later hoping any remote depedency that had broken might be repaired but same result.
And then I walked away and came back 30 minutes later to find Cura loaded(!!!) which seems to indicate my profiles/settings are still valid.
Trying to repro I found that Cura hangs for 20 mintutes between the 2 below log lines, with no indication why, but all loading before and after the hang proceeds as normal.

**This happens on multiple machines with vastly different hardware installed that all worked just fine this time last week but now all suffer this issue with no changes on my part.

Screenshot(s)
N/A

Actual results
App startup hangs for 20 minutes

Expected results
No delay should occur

Project file
N/A

Log file
(TLDR)
2020-10-26 15:39:25,034 - DEBUG - [MainThread] UM.PluginRegistry.loadPlugins [373]: Loading all plugins took 2.7668869495391846 seconds
2020-10-26 15:39:25,049 - INFO - [MainThread] UM.VersionUpgradeManager.upgrade [163]: Looking for old configuration files to upgrade.
2020-10-26 15:39:25,400 - INFO - [MainThread] UM.VersionUpgradeManager.upgrade [175]: Checking and performing updates took 0.35339903831481934
2020-10-26 15:58:18,186 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.loadAllMetadata [361]: Loading metadata into container registry took 1.0665972232818604 seconds

2020-10-26 15:58:18,203 - DEBUG - [MainThread] cura.Scene.CuraSceneController.setActiveBuildPlate [142]: Select build plate: 0

20 minutes bewtween log lines with no error or warning

(FULL)
will provided if needed

Additional information
repro'd on fully loaded core7/intel grfx Lenovo X1 Yoga and custom Desktop AMD Threadripper / Radeon 7 grfx fast and lots of ram/pcie ssd.

@bryanhunwardsen bryanhunwardsen added the Type: Bug The code does not produce the intended behavior. label Oct 26, 2020
@bryanhunwardsen
Copy link
Author

bryanhunwardsen commented Oct 26, 2020

Here is a longer log snippet from my desktop, the delay is still there but closer to 5 minutes which may reflect the compute differential compared to the OP log provided from my laptop.

2020-10-23 17:32:07,385 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin FileLogger
2020-10-23 17:32:07,404 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin FirmwareUpdateChecker
2020-10-23 17:32:07,418 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin FirmwareUpdater
2020-10-23 17:32:07,429 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin GCodeGzReader
2020-10-23 17:32:07,442 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin GCodeGzWriter
2020-10-23 17:32:07,455 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin GCodeProfileReader
2020-10-23 17:32:07,481 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin GCodeReader
2020-10-23 17:32:07,494 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin GCodeWriter
2020-10-23 17:32:07,513 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin ImageReader
2020-10-23 17:32:07,526 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin LegacyProfileReader
2020-10-23 17:32:07,539 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin LocalContainerProvider
2020-10-23 17:32:07,556 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin LocalFileOutputDevice
2020-10-23 17:32:07,570 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin MachineSettingsAction
2020-10-23 17:32:07,584 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin ModelChecker
2020-10-23 17:32:07,597 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin MonitorStage
2020-10-23 17:32:07,613 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin PerObjectSettingsTool
2020-10-23 17:32:07,629 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin PostProcessingPlugin
2020-10-23 17:32:07,641 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin PrepareStage
2020-10-23 17:32:07,652 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin PreviewStage
2020-10-23 17:32:07,670 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin RemovableDriveOutputDevice
2020-10-23 17:32:07,681 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin SentryLogger
2020-10-23 17:32:07,711 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin SimulationView
2020-10-23 17:32:07,728 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin SliceInfoPlugin
2020-10-23 17:32:07,745 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin SolidView
2020-10-23 17:32:07,761 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin SupportEraser
2020-10-23 17:32:07,809 - WARNING - [MainThread] UM.Logger.logException [106]: Exception: Failed to load packages for Marketplace
2020-10-23 17:32:07,813 - WARNING - [MainThread] UM.Logger.logException [110]: NoneType: None
2020-10-23 17:32:07,817 - WARNING - [MainThread] UM.Logger.logException [106]: Exception: Failed to load packages for Marketplace
2020-10-23 17:32:07,821 - WARNING - [MainThread] UM.Logger.logException [110]: NoneType: None
2020-10-23 17:32:07,825 - WARNING - [MainThread] UM.Logger.logException [106]: Exception: Failed to load packages for Marketplace
2020-10-23 17:32:07,829 - WARNING - [MainThread] UM.Logger.logException [110]: NoneType: None
2020-10-23 17:32:07,832 - WARNING - [MainThread] UM.Logger.logException [106]: Exception: Failed to load packages for Marketplace
2020-10-23 17:32:07,836 - WARNING - [MainThread] UM.Logger.logException [110]: NoneType: None
2020-10-23 17:32:07,848 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin Toolbox
2020-10-23 17:32:07,863 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin CameraTool
2020-10-23 17:32:07,881 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin MirrorTool
2020-10-23 17:32:07,903 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin RotateTool
2020-10-23 17:32:07,922 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin ScaleTool
2020-10-23 17:32:07,937 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin SelectionTool
2020-10-23 17:32:07,957 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin TranslateTool
2020-10-23 17:32:07,970 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin TrimeshReader
2020-10-23 17:32:07,991 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin UFPReader
2020-10-23 17:32:08,009 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin UFPWriter
2020-10-23 17:32:08,025 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin UltimakerMachineActions
2020-10-23 17:32:08,208 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin UM3NetworkPrinting
2020-10-23 17:32:08,223 - INFO - [Thread-1] UpdateChecker.UpdateCheckerJob.run [40]: Checking for new version of cura
2020-10-23 17:32:08,229 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin UpdateChecker
2020-10-23 17:32:08,720 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin USBPrinting
2020-10-23 17:32:08,938 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade21to22
2020-10-23 17:32:09,004 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade22to24
2020-10-23 17:32:09,070 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade25to26
2020-10-23 17:32:09,136 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade26to27
2020-10-23 17:32:09,211 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade27to30
2020-10-23 17:32:09,233 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade30to31
2020-10-23 17:32:09,249 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade32to33
2020-10-23 17:32:09,264 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade33to34
2020-10-23 17:32:09,280 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade34to35
2020-10-23 17:32:09,295 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade35to40
2020-10-23 17:32:09,310 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade40to41
2020-10-23 17:32:09,327 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade41to42
2020-10-23 17:32:09,342 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade42to43
2020-10-23 17:32:09,356 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade43to44
2020-10-23 17:32:09,365 - DEBUG - [MainThread] VersionUpgrade44to45.VersionUpgrade44to45.removeHiddenStacks [63]: Removing all hidden container stacks.
2020-10-23 17:32:09,401 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade44to45
2020-10-23 17:32:09,414 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade45to46
2020-10-23 17:32:09,427 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade460to462
2020-10-23 17:32:09,443 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade462to47
2020-10-23 17:32:09,456 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin SimpleView
2020-10-23 17:32:09,476 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin X3DReader
2020-10-23 17:32:09,499 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin XmlMaterialProfile
2020-10-23 17:32:09,514 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin XRayView
2020-10-23 17:32:09,535 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin CustomJobPrefix
2020-10-23 17:32:09,547 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin CustomSupports
2020-10-23 17:32:09,561 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin DuetRRFPlugin
2020-10-23 17:32:09,572 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin GcodeFilenameFormat
2020-10-23 17:32:09,592 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin HTMLCuraSettings
2020-10-23 17:32:09,603 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin LinearAdvanceSettingPlugin
2020-10-23 17:32:09,617 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin MeshTools
2020-10-23 17:32:09,634 - WARNING - [MainThread] OctoPrintPlugin.OctoPrintOutputDevicePlugin.<module> [49]: Supplied version of Zeroconf module imported
2020-10-23 17:32:09,651 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin OctoPrintPlugin
2020-10-23 17:32:09,663 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin OrientationPlugin
2020-10-23 17:32:09,674 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin PauseBackendPlugin
2020-10-23 17:32:09,686 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin PrinterSettingsPlugin
2020-10-23 17:32:09,697 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin SettingVisibilityProfileCreator
2020-10-23 17:32:09,706 - DEBUG - [MainThread] SidebarGUIPlugin.SidebarGUIProxy.__init__ [18]: SidebarGUI proxy created
2020-10-23 17:32:09,713 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin SidebarGUIPlugin
2020-10-23 17:32:09,743 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin ThingiBrowser
2020-10-23 17:32:09,754 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionInTitlebarPlugin
2020-10-23 17:32:09,764 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin ZOffsetPlugin
2020-10-23 17:32:09,768 - DEBUG - [MainThread] UM.PluginRegistry.loadPlugins [373]: Loading all plugins took 3.280001163482666 seconds
2020-10-23 17:32:09,792 - INFO - [MainThread] UM.VersionUpgradeManager.upgrade [163]: Looking for old configuration files to upgrade.
2020-10-23 17:32:10,213 - INFO - [MainThread] UM.VersionUpgradeManager.upgrade [175]: Checking and performing updates took 0.42099976539611816
2020-10-23 17:38:26,894 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin FileLogger
2020-10-23 17:38:26,912 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin FirmwareUpdateChecker
2020-10-23 17:38:26,925 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin FirmwareUpdater
2020-10-23 17:38:26,936 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin GCodeGzReader
2020-10-23 17:38:26,948 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin GCodeGzWriter
2020-10-23 17:38:26,961 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin GCodeProfileReader
2020-10-23 17:38:26,985 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin GCodeReader
2020-10-23 17:38:26,999 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin GCodeWriter
2020-10-23 17:38:27,016 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin ImageReader
2020-10-23 17:38:27,029 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin LegacyProfileReader
2020-10-23 17:38:27,042 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin LocalContainerProvider
2020-10-23 17:38:27,058 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin LocalFileOutputDevice
2020-10-23 17:38:27,070 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin MachineSettingsAction
2020-10-23 17:38:27,083 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin ModelChecker
2020-10-23 17:38:27,097 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin MonitorStage
2020-10-23 17:38:27,111 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin PerObjectSettingsTool
2020-10-23 17:38:27,124 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin PostProcessingPlugin
2020-10-23 17:38:27,137 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin PrepareStage
2020-10-23 17:38:27,148 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin PreviewStage
2020-10-23 17:38:27,166 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin RemovableDriveOutputDevice
2020-10-23 17:38:27,177 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin SentryLogger
2020-10-23 17:38:27,207 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin SimulationView
2020-10-23 17:38:27,222 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin SliceInfoPlugin
2020-10-23 17:38:27,239 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin SolidView
2020-10-23 17:38:27,253 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin SupportEraser
2020-10-23 17:38:27,298 - WARNING - [MainThread] UM.Logger.logException [106]: Exception: Failed to load packages for Marketplace
2020-10-23 17:38:27,301 - WARNING - [MainThread] UM.Logger.logException [110]: NoneType: None
2020-10-23 17:38:27,305 - WARNING - [MainThread] UM.Logger.logException [106]: Exception: Failed to load packages for Marketplace
2020-10-23 17:38:27,309 - WARNING - [MainThread] UM.Logger.logException [110]: NoneType: None
2020-10-23 17:38:27,313 - WARNING - [MainThread] UM.Logger.logException [106]: Exception: Failed to load packages for Marketplace
2020-10-23 17:38:27,316 - WARNING - [MainThread] UM.Logger.logException [110]: NoneType: None
2020-10-23 17:38:27,320 - WARNING - [MainThread] UM.Logger.logException [106]: Exception: Failed to load packages for Marketplace
2020-10-23 17:38:27,324 - WARNING - [MainThread] UM.Logger.logException [110]: NoneType: None
2020-10-23 17:38:27,335 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin Toolbox
2020-10-23 17:38:27,349 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin CameraTool
2020-10-23 17:38:27,364 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin MirrorTool
2020-10-23 17:38:27,385 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin RotateTool
2020-10-23 17:38:27,404 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin ScaleTool
2020-10-23 17:38:27,416 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin SelectionTool
2020-10-23 17:38:27,433 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin TranslateTool
2020-10-23 17:38:27,445 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin TrimeshReader
2020-10-23 17:38:27,465 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin UFPReader
2020-10-23 17:38:27,480 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin UFPWriter
2020-10-23 17:38:27,494 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin UltimakerMachineActions
2020-10-23 17:38:27,664 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin UM3NetworkPrinting
2020-10-23 17:38:27,677 - INFO - [Thread-1] UpdateChecker.UpdateCheckerJob.run [40]: Checking for new version of cura
2020-10-23 17:38:27,682 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin UpdateChecker
2020-10-23 17:38:27,952 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin USBPrinting
2020-10-23 17:38:28,161 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade21to22
2020-10-23 17:38:28,232 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade22to24
2020-10-23 17:38:28,303 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade25to26
2020-10-23 17:38:28,392 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade26to27
2020-10-23 17:38:28,466 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade27to30
2020-10-23 17:38:28,530 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade30to31
2020-10-23 17:38:28,593 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade32to33
2020-10-23 17:38:28,637 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade33to34
2020-10-23 17:38:28,694 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade34to35
2020-10-23 17:38:28,710 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade35to40
2020-10-23 17:38:28,724 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade40to41
2020-10-23 17:38:28,740 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade41to42
2020-10-23 17:38:28,756 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade42to43
2020-10-23 17:38:28,772 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade43to44
2020-10-23 17:38:28,783 - DEBUG - [MainThread] VersionUpgrade44to45.VersionUpgrade44to45.removeHiddenStacks [63]: Removing all hidden container stacks.
2020-10-23 17:38:28,827 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade44to45
2020-10-23 17:38:28,842 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade45to46
2020-10-23 17:38:28,854 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade460to462
2020-10-23 17:38:28,867 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionUpgrade462to47
2020-10-23 17:38:28,879 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin SimpleView
2020-10-23 17:38:28,900 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin X3DReader
2020-10-23 17:38:28,931 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin XmlMaterialProfile
2020-10-23 17:38:28,945 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin XRayView
2020-10-23 17:38:28,967 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin CustomJobPrefix
2020-10-23 17:38:28,979 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin CustomSupports
2020-10-23 17:38:28,993 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin DuetRRFPlugin
2020-10-23 17:38:29,005 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin GcodeFilenameFormat
2020-10-23 17:38:29,026 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin HTMLCuraSettings
2020-10-23 17:38:29,037 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin LinearAdvanceSettingPlugin
2020-10-23 17:38:29,051 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin MeshTools
2020-10-23 17:38:29,067 - WARNING - [MainThread] OctoPrintPlugin.OctoPrintOutputDevicePlugin.<module> [49]: Supplied version of Zeroconf module imported
2020-10-23 17:38:29,083 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin OctoPrintPlugin
2020-10-23 17:38:29,096 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin OrientationPlugin
2020-10-23 17:38:29,107 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin PauseBackendPlugin
2020-10-23 17:38:29,117 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin PrinterSettingsPlugin
2020-10-23 17:38:29,129 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin SettingVisibilityProfileCreator
2020-10-23 17:38:29,139 - DEBUG - [MainThread] SidebarGUIPlugin.SidebarGUIProxy.__init__ [18]: SidebarGUI proxy created
2020-10-23 17:38:29,146 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin SidebarGUIPlugin
2020-10-23 17:38:29,176 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin ThingiBrowser
2020-10-23 17:38:29,185 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin VersionInTitlebarPlugin
2020-10-23 17:38:29,196 - INFO - [MainThread] UM.Logger.info [122]: Loaded plugin ZOffsetPlugin
2020-10-23 17:38:29,200 - DEBUG - [MainThread] UM.PluginRegistry.loadPlugins [373]: Loading all plugins took 3.1499998569488525 seconds
2020-10-23 17:38:29,223 - INFO - [MainThread] UM.VersionUpgradeManager.upgrade [163]: Looking for old configuration files to upgrade.
**2020-10-23 17:38:29,629 - INFO - [MainThread] UM.VersionUpgradeManager.upgrade [175]: Checking and performing updates took 0.40601444244384766
2020-10-23 18:43:03,124 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.loadAllMetadata [361]: Loading metadata into container registry took 17.62798309326172 seconds**
2020-10-23 18:43:03,142 - DEBUG - [MainThread] cura.Scene.CuraSceneController.setActiveBuildPlate [142]: Select build plate: 0
2020-10-23 18:43:03,147 - INFO - [MainThread] cura.CuraApplication.run [781]: Initializing machine error checker
2020-10-23 18:43:03,767 - WARNING - [MainThread] LocalContainerProvider.LocalContainerProvider._saveCachedDefinition [295]: The definition cache for definition creality_ender3pro failed to pickle.
2020-10-23 18:43:03,794 - INFO - [MainThread] cura.UI.MachineActionManager.addDefaultMachineActions [74]: Default machine actions added for machine definition [creality_ender3pro]
2020-10-23 18:43:04,261 - WARNING - [MainThread] LocalContainerProvider.LocalContainerProvider._saveCachedDefinition [295]: The definition cache for definition creality_base failed to pickle.
2020-10-23 18:43:04,373 - INFO - [MainThread] cura.Settings.GlobalStack.addExtruder [194]: Extruder[creality_base_extruder_0 #3] added to [Ender3 V2] at position [0]
2020-10-23 18:43:04,374 - INFO - [MainThread] FirmwareUpdateChecker.FirmwareUpdateChecker.checkFirmwareVersion [79]: No machine with name Creality Ender-3 Pro in list of firmware to check.
2020-10-23 18:43:05,304 - DEBUG - [MainThread] cura.Machines.ContainerTree.__getitem__ [120]: Adding container tree for creality_ender3pro took 0.9180171489715576 seconds.
2020-10-23 18:43:05,337 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [202]: Begin loading of script: ChangeAtZ
2020-10-23 18:43:05,347 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [202]: Begin loading of script: ColorMix
2020-10-23 18:43:05,357 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [202]: Begin loading of script: DisplayFilenameAndLayerOnLCD
2020-10-23 18:43:05,367 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [202]: Begin loading of script: DisplayProgressOnLCD
2020-10-23 18:43:05,376 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [202]: Begin loading of script: FilamentChange
2020-10-23 18:43:05,385 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [202]: Begin loading of script: InsertAtLayerChange
2020-10-23 18:43:05,396 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [202]: Begin loading of script: PauseAtHeight
2020-10-23 18:43:05,406 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [202]: Begin loading of script: RetractContinue
2020-10-23 18:43:05,414 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [202]: Begin loading of script: SearchAndReplace
2020-10-23 18:43:05,427 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [202]: Begin loading of script: Stretch
2020-10-23 18:43:05,436 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [202]: Begin loading of script: TimeLapse
2020-10-23 18:43:05,444 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [202]: Begin loading of script: UsePreviousProbeMeasurements
2020-10-23 18:43:05,789 - WARNING - [MainThread] LocalContainerProvider.LocalContainerProvider._saveCachedDefinition [295]: The definition cache for definition fdmprinter failed to pickle.
2020-10-23 18:43:05,858 - INFO - [MainThread] cura.CuraApplication.run [786]: Initializing machine manager
2020-10-23 18:43:05,865 - INFO - [MainThread] cura.CuraApplication.run [791]: Initializing container manager
2020-10-23 18:43:05,915 - DEBUG - [Thread-2] UM.Mesh.MeshData.calculateNormalsFromVertices [552]: Calculating normals took 0.002000093460083008 seconds
2020-10-23 18:43:05,938 - DEBUG - [Thread-2] UM.Mesh.MeshData.approximateConvexHull [506]: approximateConvexHull(target_count=1024) Calculating 3D convex hull took 0.011999130249023438 seconds. 8 input vertices. 8 output vertices.
2020-10-23 18:43:06,613 - WARNING - [MainThread] cura.OAuth2.AuthorizationHelpers.parseJWT [118]: Could not retrieve token data from auth server: {"errors": [{"id": "19c988c4-f954-46d4-87ce-d4382d6417c3", "code": "tokenExpired", "http_status": "403", "title": "The given token has expired.", "meta": {"error_type": "AuthError", "url": "https://account.ultimaker.com/check-token"}}]}
2020-10-23 18:43:06,616 - DEBUG - [MainThread] cura.OAuth2.AuthorizationHelpers.getAccessTokenUsingRefreshToken [60]: Refreshing the access token.
2020-10-23 18:43:07,297 - DEBUG - [MainThread] cura.OAuth2.AuthorizationService._storeAuthData [250]: Attempting to store the auth data
2020-10-23 18:43:08,651 - WARNING - [MainThread] UM.Logger.warning [128]: Starting a new sync while previous sync was not completed
{'CloudOutputDeviceManager': 0}
2020-10-23 18:43:09,867 - DEBUG - [MainThread] cura.Machines.MachineErrorChecker._rescheduleCheck [155]: New error check scheduled.
2020-10-23 18:43:09,878 - DEBUG - [MainThread] cura.PrinterOutput.NetworkedPrinterOutputDevice._createNetworkManager [318]: Creating network manager
2020-10-23 18:43:09,892 - DEBUG - [MainThread] OctoPrintPlugin.OctoPrintOutputDevice.connect [341]: Connection with instance OctoPi4 with url http://hunwardsen.com:5004/ started
2020-10-23 18:43:09,959 - DEBUG - [MainThread] UM.Scene.Camera._preferencesChanged [255]: Changing perspective mode to perspective.
2020-10-23 18:43:10,065 - DEBUG - [zeroconf-ServiceBrowser__octoprint._tcp.local.] OctoPrintPlugin.OctoPrintOutputDevicePlugin._onServiceChanged [288]: Bonjour service added: "Alien Octoprint"._octoprint._tcp.local
2020-10-23 18:43:10,135 - INFO - [MainThread] UM.OutputDevice.OutputDeviceManager.addOutputDevice [171]: Output Device OctoPi4 already added
2020-10-23 18:43:10,223 - DEBUG - [MainThread] UM.Qt.Bindings.Theme.load [158]: Loading theme file: C:\Program Files\Ultimaker Cura 4.7\resources\themes\cura-dark\theme.json
2020-10-23 18:43:10,237 - DEBUG - [MainThread] UM.Qt.Bindings.Theme.load [158]: Loading theme file: C:\Program Files\Ultimaker Cura 4.7\resources\themes\cura-light\theme.json
2020-10-23 18:43:11,456 - DEBUG - [MainThread] UM.Qt.Bindings.Theme.load [246]: Loaded theme C:\Program Files\Ultimaker Cura 4.7\resources\themes\cura-light
2020-10-23 18:43:11,461 - DEBUG - [MainThread] UM.Qt.Bindings.Theme.load [246]: Loaded theme C:\Program Files\Ultimaker Cura 4.7\resources\themes\cura-dark
2020-10-23 18:43:14,037 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin._createView [336]: Creating post processing plugin view.
2020-10-23 18:43:14,430 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin._createView [346]: Post processing view created.
2020-10-23 18:43:14,757 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [406]: file:///C:/Program Files/Ultimaker Cura 4.7/qml/QtQuick/Controls/Private/BasicTableView.qml:613:17: QML QQuickItem*: Binding loop detected for property "width"
2020-10-23 18:43:15,612 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [406]: file:///C:/Program Files/Ultimaker Cura 4.7/resources/qml/Account/UserOperations.qml:17:5: QML QQuickItem: Binding loop detected for property "height"
2020-10-23 18:43:15,616 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [406]: file:///C:/Program Files/Ultimaker Cura 4.7/resources/qml/Account/UserOperations.qml:17:5: QML QQuickItem: Binding loop detected for property "height"
2020-10-23 18:43:15,654 - DEBUG - [MainThread] cura.Machines.Models.NozzleModel._update [28]: Updating NozzleModel.
2020-10-23 18:43:15,853 - DEBUG - [MainThread] CustomJobPrefix.CustomJobPrefix._createAdditionalComponentsView [40]: Creating additional ui components for CustomJobPrefix
2020-10-23 18:43:15,923 - DEBUG - [MainThread] MeshTools.MeshTools._onEngineCreated [113]: Inserting item in context menu
2020-10-23 18:43:15,968 - DEBUG - [MainThread] OctoPrintPlugin.DiscoverOctoPrintAction._createAdditionalComponentsView [426]: Creating additional ui components for OctoPrint-connected printers.
2020-10-23 18:43:16,009 - DEBUG - [MainThread] PauseBackendPlugin.PauseBackend._createAdditionalComponentsView [27]: Creating additional ui components for Pause Backend plugin.
2020-10-23 18:43:16,060 - DEBUG - [MainThread] SidebarGUIPlugin.SidebarGUIPlugin._onEngineCreated [39]: Registering replacement stages
2020-10-23 18:43:16,067 - DEBUG - [MainThread] UM.Controller.setActiveStage [180]: Setting active stage to PrepareStage
2020-10-23 18:43:16,071 - DEBUG - [MainThread] UM.Controller.setActiveView [108]: Setting active view to SolidView
2020-10-23 18:43:16,522 - DEBUG - [MainThread] cura.Machines.Models.NozzleModel._update [28]: Updating NozzleModel.
2020-10-23 18:43:16,723 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [406]: file:///C:/Users/bryan/AppData/Roaming/cura/4.7/plugins/SidebarGUIPlugin/SidebarGUIPlugin/resources/qml/ProfileSelector44.qml:38:5: QML Button: Binding loop detected for property "implicitWidth"
2020-10-23 18:43:16,774 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [406]: file:///C:/Users/bryan/AppData/Roaming/cura/4.7/plugins/SidebarGUIPlugin/SidebarGUIPlugin/resources/qml/ViewOptionsPanel.qml:148:13: QML QQuickItem: Binding loop detected for property "children"
2020-10-23 18:43:16,778 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [406]: file:///C:/Users/bryan/AppData/Roaming/cura/4.7/plugins/SidebarGUIPlugin/SidebarGUIPlugin/resources/qml/ViewOptionsPanel.qml:148:13: QML QQuickItem: Binding loop detected for property "children"
2020-10-23 18:43:16,781 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [406]: file:///C:/Users/bryan/AppData/Roaming/cura/4.7/plugins/SidebarGUIPlugin/SidebarGUIPlugin/resources/qml/ViewOptionsPanel.qml:148:13: QML QQuickItem: Binding loop detected for property "children"
2020-10-23 18:43:16,785 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [406]: file:///C:/Users/bryan/AppData/Roaming/cura/4.7/plugins/SidebarGUIPlugin/SidebarGUIPlugin/resources/qml/ViewOptionsPanel.qml:148:13: QML QQuickItem: Binding loop detected for property "children"
2020-10-23 18:43:16,817 - DEBUG - [MainThread] cura.CuraApplication.log [1716]: SidebarGUIPlugin patching interface for Cura 4.7 and newer
2020-10-23 18:43:16,824 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [406]: file:///C:/Program Files/Ultimaker Cura 4.7/resources/qml/PrintSetupSelector/PrintSetupSelector.qml:33:18: QML PrintSetupSelectorContents: Possible anchor loop detected on fill.
2020-10-23 18:43:16,847 - DEBUG - [MainThread] UM.Controller.setActiveView [108]: Setting active view to SolidView
2020-10-23 18:43:16,853 - DEBUG - [MainThread] ModelChecker.ModelChecker._createView [117]: Creating model checker view.
2020-10-23 18:43:16,874 - DEBUG - [MainThread] ModelChecker.ModelChecker._createView [126]: Model checker view created.
2020-10-23 18:43:16,875 - DEBUG - [MainThread] SliceInfoPlugin.SliceInfo._createDialog [76]: Creating dialog [MoreInfoWindow.qml]
2020-10-23 18:43:16,979 - DEBUG - [MainThread] Toolbox.src.Toolbox._makeRequestByType [544]: Requesting [updates] metadata from server.
2020-10-23 18:43:17,580 - WARNING - [MainThread] LocalContainerProvider.LocalContainerProvider._saveCachedDefinition [295]: The definition cache for definition creality_cr10s failed to pickle.
2020-10-23 18:43:18,072 - WARNING - [MainThread] LocalContainerProvider.LocalContainerProvider._saveCachedDefinition [295]: The definition cache for definition custom failed to pickle.
2020-10-23 18:43:18,621 - WARNING - [MainThread] LocalContainerProvider.LocalContainerProvider._saveCachedDefinition [295]: The definition cache for definition deltabot failed to pickle.
2020-10-23 18:43:18,658 - DEBUG - [MainThread] cura.CuraApplication.run [830]: Booting Cura took 3893.6500136852264 seconds
2020-10-23 18:43:18,664 - DEBUG - [Thread-3] cura.Machines.ContainerTree.run [174]: Started background loading of MachineNodes
2020-10-23 18:43:18,678 - INFO - [MainThread] FirmwareUpdateChecker.FirmwareUpdateChecker.checkFirmwareVersion [79]: No machine with name Creality CR-10S in list of firmware to check.
2020-10-23 18:43:18,679 - INFO - [MainThread] FirmwareUpdateChecker.FirmwareUpdateChecker.checkFirmwareVersion [79]: No machine with name Custom FFF printer in list of firmware to check.
2020-10-23 18:43:18,687 - DEBUG - [MainThread] cura.Machines.Models.CustomQualityProfilesDropDownMenuModel._update [33]: Updating CustomQualityProfilesDropDownMenuModel.
2020-10-23 18:43:18,702 - DEBUG - [MainThread] cura.Machines.Models.CustomQualityProfilesDropDownMenuModel._update [33]: Updating CustomQualityProfilesDropDownMenuModel.
2020-10-23 18:43:18,704 - INFO - [MainThread] FirmwareUpdateChecker.FirmwareUpdateChecker.checkFirmwareVersion [79]: No machine with name DeltaBot in list of firmware to check.
2020-10-23 18:43:18,721 - WARNING - [MainThread] UM.Decorators.deprecated_function [23]: <function GlobalStack.extruders at 0x000001FCB590BE18> is deprecated (since 4.4): Please use extruderList instead.
2020-10-23 18:43:18,739 - DEBUG - [MainThread] cura.Machines.Models.CustomQualityProfilesDropDownMenuModel._update [33]: Updating CustomQualityProfilesDropDownMenuModel.
2020-10-23 18:43:18,745 - DEBUG - [MainThread] cura.Machines.Models.QualityProfilesDropDownMenuModel._update [62]: Updating QualityProfilesDropDownMenuModel.
2020-10-23 18:43:19,083 - DEBUG - [MainThread] cura.Machines.Models.QualityProfilesDropDownMenuModel._update [62]: Updating QualityProfilesDropDownMenuModel.
2020-10-23 18:43:19,092 - DEBUG - [MainThread] cura.Machines.Models.CustomQualityProfilesDropDownMenuModel._update [33]: Updating CustomQualityProfilesDropDownMenuModel.
2020-10-23 18:43:20,022 - DEBUG - [Thread-3] cura.Machines.ContainerTree.__getitem__ [120]: Adding container tree for creality_cr10s took 0.8510136604309082 seconds.
2020-10-23 18:43:20,182 - DEBUG - [MainThread] UM.Qt.QtRenderer._initialize [210]: Support for Vertex Array Objects: True
2020-10-23 18:43:20,211 - DEBUG - [MainThread] UM.View.GL.OpenGL.__init__ [112]: Initialized OpenGL subsystems.
2020-10-23 18:43:20,215 - DEBUG - [MainThread] UM.View.GL.OpenGL.__init__ [113]: OpenGL Version:  4.1.13587 Core Profile Forward-Compatible Context 20.4.2 26.20.15029.27017
2020-10-23 18:43:20,219 - DEBUG - [MainThread] UM.View.GL.OpenGL.__init__ [114]: OpenGL Vendor:   ATI Technologies Inc.
2020-10-23 18:43:20,223 - DEBUG - [MainThread] UM.View.GL.OpenGL.__init__ [115]: OpenGL Renderer: AMD Radeon VII
2020-10-23 18:43:20,227 - DEBUG - [MainThread] UM.View.GL.OpenGL.__init__ [116]: GLSL Version:    4.60.0
2020-10-23 18:43:20,232 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [58]: Loading shader file [C:\Program Files\Ultimaker Cura 4.7\resources\shaders\default.shader]...
2020-10-23 18:43:20,246 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [58]: Loading shader file [C:\Program Files\Ultimaker Cura 4.7\resources\shaders\selection.shader]...
2020-10-23 18:43:20,258 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [58]: Loading shader file [C:\Program Files\Ultimaker Cura 4.7\resources\shaders\select_face.shader]...
2020-10-23 18:43:20,272 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [58]: Loading shader file [C:\Program Files\Ultimaker Cura 4.7\resources\shaders\default.shader]...
2020-10-23 18:43:20,278 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [58]: Loading shader file [C:\Program Files\Ultimaker Cura 4.7\resources\shaders\composite.shader]...
2020-10-23 18:43:20,294 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [58]: Loading shader file [C:\Program Files\Ultimaker Cura 4.7\resources\shaders\overhang.shader]...
2020-10-23 18:43:20,309 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [58]: Loading shader file [C:\Program Files\Ultimaker Cura 4.7\resources\shaders\striped.shader]...
2020-10-23 18:43:20,322 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [58]: Loading shader file [C:\Program Files\Ultimaker Cura 4.7\resources\shaders\transparent_object.shader]...
2020-10-23 18:43:20,335 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [58]: Loading shader file [C:\Program Files\Ultimaker Cura 4.7\resources\shaders\striped.shader]...
2020-10-23 18:43:20,341 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [58]: Loading shader file [C:\Program Files\Ultimaker Cura 4.7\resources\shaders\default.shader]...
2020-10-23 18:43:20,346 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [58]: Loading shader file [C:\Program Files\Ultimaker Cura 4.7\resources\shaders\grid.shader]...
2020-10-23 18:43:20,360 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [58]: Loading shader file [C:\Program Files\Ultimaker Cura 4.7\resources\shaders\platform.shader]...
2020-10-23 18:43:20,744 - DEBUG - [Thread-3] cura.Machines.ContainerTree.__getitem__ [120]: Adding container tree for custom took 0.21600008010864258 seconds.
2020-10-23 18:43:21,921 - INFO - [MainThread] cura.Machines.MachineErrorChecker._setResult [214]: Error check finished, result = False, time = 12.1s
2020-10-23 18:43:22,969 - DEBUG - [Thread-3] cura.Machines.ContainerTree.__getitem__ [120]: Adding container tree for deltabot took 0.21093344688415527 seconds.
2020-10-23 18:43:22,973 - DEBUG - [Thread-3] cura.Machines.ContainerTree.run [185]: All MachineNode loading completed
2020-10-23 18:43:30,881 - DEBUG - [MainThread] cura.AutoSave._onTimeout [59]: Autosaving preferences, instances and profiles
2020-10-23 18:52:23,145 - DEBUG - [MainThread] cura.OAuth2.AuthorizationHelpers.getAccessTokenUsingRefreshToken [60]: Refreshing the access token.
2020-10-23 18:52:23,847 - DEBUG - [MainThread] cura.OAuth2.AuthorizationService._storeAuthData [250]: Attempting to store the auth data
2020-10-23 18:52:33,845 - DEBUG - [MainThread] cura.AutoSave._onTimeout [59]: Autosaving preferences, instances and profiles
2020-10-23 19:01:27,411 - DEBUG - [MainThread] cura.OAuth2.AuthorizationHelpers.getAccessTokenUsingRefreshToken [60]: Refreshing the access token.
2020-10-23 19:01:28,243 - DEBUG - [MainThread] cura.OAuth2.AuthorizationService._storeAuthData [250]: Attempting to store the auth data
2020-10-23 19:01:38,238 - DEBUG - [MainThread] cura.AutoSave._onTimeout [59]: Autosaving preferences, instances and profiles

@fieldOfView
Copy link
Collaborator

Do you perhaps have a drive mapped to the letter X that is not currently connected? If so, could you try mapping that drive to a different driveletter?

@bryanhunwardsen
Copy link
Author

@fieldOfView On my Desktop I have a network drive mapped to "S:" and nothing on my laptop, neither has any mapping or drives assigned to "X:"

@Ghostkeeper
Copy link
Collaborator

We can rule out the version upgrade and the loading of the metadata here. Both are timed almost completely. These are the things that are done in between, in the start-up sequence:

  • Loading preferences file (the splash window also shows "loading preferences..." then)
  • Check if you are running a new version of Cura for the first time (so change log should be shown then).
  • Filling list of recent files.
  • Adding system tray icon.
  • Loading translation catalogue for Cura.
  • Connect some signals for when the scene gets updated. One of these is on a 0.5s delay which may have had a reason that could be defeated by slow performance.
  • At this point the splash screen says "loading machines...".
  • Obtain the lock file to prepare loading the profile metadata.

One thing that could feasibly take a long time is adding the system tray icon, since that is kind of dependent on the operating system which is at liberty to block such things. This is also a visible part of the process. Perhaps you can start Cura to see if the system tray icon is there? If it is, the slow part must be somewhere after that in the process. If there is no system tray icon, the slow part was before that or the system tray icon itself.

Another thing that would help is to have more logging in our code regarding this. There are quite a few steps here that don't get a log entry. They should though...

@bryanhunwardsen
Copy link
Author

@Ghostkeeper I tried to re-run to check tray icon, alas it is now loading correctly.
Neither machine has been rebooted, or been used for much else other than testing this Cura bug during this time, which again leads me to believe there is a remote resource disturbance that caused the issue. For a bug like this to replicate so perfectly across machines, break at the same time, and resolve identically, with no changes on my end, typically points to either a remote resource or some type of datetime bug.

I guess this can technically be closed now, but, having Cura magically break and become unusable for a week, then magically fix itself, is problematic at best. I would suggest if this can somehow get in someone's backlog, to add the additional logging you indicated above, otherwise it will be near impossible to troubleshoot this if it crops up again.

Thanks for the support
humblest regards-

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Type: Bug The code does not produce the intended behavior.
Projects
None yet
Development

No branches or pull requests

3 participants