search

Ultimaker / Cura

3D printer / slicing GUI built on top of the Uranium framework
GNU Lesser General Public License v3.0
6.2k stars 2.08k forks source link

[4.2.1] UpdateChecker crash cura on startup #6152

Closed bvalat closed 5 years ago

bvalat commented 5 years ago

Application Version 4.2.1

Platform Win 10 64

Printer Ender 3 (should not be relevant)

Steps to Reproduce Install and try to start.

Actual Results Cura crash during version check. Logs just shows the loading of the UpdateChecker plugin and stop here

Expected results Cura starting.

Additional Information I removed the UpdateChecker plugin from cura directory and cura starts. I tried with Cura 4.1 UpdateChecker, it works as well. I made a diff between the two version, seems like the only diff is the activation of https instead of http. So maybe a problem with TLS code?

diegopradogesto commented 5 years ago

We noticed that for some people (mainly using macOS or Linux) the update checker doesn't work because of the SSL certificates. However we tested on Windows and it works and it should never crash.

We made a fix for it but is not release yet. If we provide you a test build, could you check for us if it works and it doesn't crash?

LipuFei commented 5 years ago

Hi @bvalat , we have a master build with a potential fix for this. Could you try it for us? Be aware that although its version number is 4.1.2, it's actually built with the current master branch. It is advised to backup your cura\4.1 directory first if you have one.

https://we.tl/t-nI0EAND9Pw

bvalat commented 5 years ago

Your version crash as well. I remove the s of https and still crashing. But if i replace updatechecker plugin by the 4.1 one it works.

Ghostkeeper commented 5 years ago

This and this are the only commits made between 4.1 and 4.2. The second one there only changes some code style really, so I'd expect that replacing the plug-in of 4.2 with the version from 4.1 would result in the exact same files as removing the "s" from https.

Routout commented 5 years ago

I can confirm this also. Windows 10. Cura wont start at all. When update checker is removed it starts.

LipuFei commented 5 years ago

JIRA ticket: CURA-6698

Flangvik commented 5 years ago

I can also confirm this issue W10 64bit, however it still wont start when "UpdateChecker" is removed from plugins. 4.1.0 works fine

bvalat commented 5 years ago

In my case it seems that even if it starts, i cannot save a gcode.... I had to disable "anonymous stats". Since i never manage to sign in my utlimaker account, it seems that anything related to communicate with ultimaker website is craching cura for me : Signing in, anonymous stats, update checker. If manage to run cura from code, evrything worked fine. I reinstalled windows from scratch (i formated my system disk) and stil have the problem. Maybe if you can find something common between those 3 features, we'll find the problem.

LipuFei commented 5 years ago

Hi there, we cannot reproduce this problem on our Windows machines... Could you run "System Information" in the "Start" menu and show us your Windows versions? That may help. And any additional information would help, too. Thanks! @bvalat @SkiddieTech @Routout

Here a screenshot of my "System Information": image

Routout commented 5 years ago

I have 10 64 Pro Version 10.0.18362 Build 18362

Today again cura didn't start. I had to shut cura.exe mutiple times fron the task manager before it started. I did remove that update checker already earlier from plugins folder, so theres something else than that causing this. I couldn't find any logs from event viewer regarding this. Does Cura have any logs which could help?

LipuFei commented 5 years ago

Hi @Routout, it's the current Insider Preview version, right? 18362. @bvalat @SkiddieTech Are you also using this preview version?

Routout commented 5 years ago

I checked that I'm on normal update channel, not insider preview.

bvalat commented 5 years ago

No i'm on standard build (1903 may update). I did try yesterday the last insider build with no success so i reinstalled windows from scratch (partition formated). See https://en.wikipedia.org/wiki/Windows_10_version_history (1903 is 18362 build). I have another computer and everything seems OK. Will compare them. The non working is a beelink m1 N3450 with 6gb ram intel graphic card with win 10 familly in french 1903 fresh install from yesterday. The working one is a selfbuild I7 2600K 24Go ram nvidia gtx1070 with win10 professional in french (upgraded from familly edition). Build should be 1903 as well. Will confirm tonight.

LipuFei commented 5 years ago

I just tried on my laptop with 18362 and it seems OK.

bvalat commented 5 years ago

@Routout : Since i reinstalled my computer, i have same behaviour. I must remove updatechecker to start Cura but some times i have to start it several times before getting cura start. The non starting process seems to hang before cura loading screen and stays aroud 53Mo if i remember.

LipuFei commented 5 years ago

I checked that I'm on normal update channel, not insider preview.

You are right. 18362 is from the normal channel. For some reason I have this laptop doesn't agree on that.

bvalat commented 5 years ago

@everybody : Is your windows in english or native language (for me in french). @Lipufei : It was the "gold" prerelease build as well. so it went from fast to slow ring and then to main release.

Routout commented 5 years ago

Same behavour here also @bvalat about 53M. I have English language, but finnish formats.

bvalat commented 5 years ago

Maybe we should try to start Cura without network just to see if it's network related. (I'm at work, won't be able to test before 4 hours). I feel that is a network layer (SSL/Socket/....) conflict with something on some windows. (language, local,...)

LipuFei commented 5 years ago

Mine are on English with Dutch formats.

Maybe we should try to start Cura without network just to see if it's network related. (I'm at work, won't be able to test before 4 hours). I feel that is a network layer (SSL/Socket/....) conflict with something on some windows. (language, local,...)

I agree. Just for more info, the code that's crashing uses urllib from python to issue HTTP requests. Our python version 3.5.2 natively compiled on our build VM, and it's linked statically against OpenSSL 1.0.2h.

@Routout @bvalat @SkiddieTech Could you try something for us?

  1. Download python-3.5.2-embed-amd64.zip from https://www.python.org/downloads/release/python-352/
  2. Extract it to a folder run the python.exe in that folder.
  3. Run the following command and see if you get a crash: 
    Python 3.5.2 (v3.5.2:4def2a2901a5, Jun 25 2016, 22:18:55) [MSC v.1900 64 bit (AMD64)] on win32
Type "help", "copyright", "credits" or "license" for more information.
>>> import urllib.request
>>> f = urllib.request.urlopen("https://software.ultimaker.com/latest.json")
>>> print(f.read().decode('utf-8'))
Routout commented 5 years ago

Seem to work, but also cura works atm...

Python 3.5.2 (v3.5.2:4def2a2901a5, Jun 25 2016, 22:18:55) [MSC v.1900 64 bit (AMD64)] on win32
Type "help", "copyright", "credits" or "license" for more information.
>>> import urllib.request
>>> f = urllib.request.urlopen("https://software.ultimaker.com/latest.json")
>>> print(f.read().decode('utf-8'))
{
    "cura": {
        "Windows": {
            "major": 4,
            "minor": 2,
            "revision": 1,
            "url": "https://ultimaker.com/en/products/ultimaker-cura-software?utm_source=cura&utm_medium=software&utm_campaign=sw-update"
        },
        "Linux": {
            "major": 4,
            "minor": 2,
            "revision": 1,
            "url": "https://ultimaker.com/en/products/ultimaker-cura-software?utm_source=cura&utm_medium=software&utm_campaign=sw-update"
        },
        "Darwin": {
            "major": 4,
            "minor": 2,
            "revision": 1,
            "url": "https://ultimaker.com/en/products/ultimaker-cura-software?utm_source=cura&utm_medium=software&utm_campaign=sw-update"
        }
    }
}
LipuFei commented 5 years ago

Seem to work, but also cura works atm...

@Routout So for you it sometimes works sometimes doesn't?

LipuFei commented 5 years ago

I'm not sure but this Python issue seems related: https://bugs.python.org/issue36011

Also partially explains behaviors like once it works, it just works...

I'll do some testing to verify this.

Routout commented 5 years ago

Seem to work, but also cura works atm...

@Routout So for you it sometimes works sometimes doesn't?

Yes. I have sometimes kill process manually several times before Cura starts. Then it might startup properly a few times.

LipuFei commented 5 years ago

Please correct me if I'm wrong, but I think it's this Python issue https://bugs.python.org/issue36011

TL;DR: One way to see if it's issue 36011 is to access https://software.ultimaker.com via IE/Edge just once. Then open Cura without any modification. If it doesn't crash on that CERTIFICATE_VERIFY_FAILED error, it's very likely caused by issue 36011.

Details: I tested on a newly created Windows Server 2019 VM:

> import urllib.request
> f = urllib.request.urlopen("https://software.ultimaker.com/latest.json")
...
ssl.SSLError: [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed
>
> import ssl
> c = ssl.SSLContext(ssl.PROTOCOL_TLSv1_2)
> len(c.get_ca_certs())
0
> c.load_default_certs()
> len(c.get_ca_certs())
13   # I have 13 default CA certificates
> import urllib.request
> f = urllib.request.urlopen("https://software.ultimaker.com/latest.json")
# It works now!

> import ssl
> c = ssl.SSLContext(ssl.PROTOCOL_TLSv1_2)
> len(c.get_ca_certs())
0
> c.load_default_certs()
> len(c.get_ca_certs())
16   # Now I have 16 default CA certificates

The problem is that Windows 10 comes with a minimal number of trusted CA certificates in its default certificate store. The SSL certificate of https://software.ultimaker.com is issued by Let's Encrypt, whose CA certificate is not in the default certificate store. After you use IE/Edge to access https://software.ultimaker.com, it uses SChannel which magically fetches and stores new CA certificates into the default CA store on Windows. After this, if you try to access https://software.ultimaker.com in Python, it works.

LipuFei commented 5 years ago

@bvalat @SkiddieTech @Routout

Routout commented 5 years ago

No errors for me. But again Cura wont start...

Python 3.5.2 (v3.5.2:4def2a2901a5, Jun 25 2016, 22:18:55) [MSC v.1900 64 bit (AMD64)] on win32
Type "help", "copyright", "credits" or "license" for more information.
>>> import urllib.request
>>> f = urllib.request.urlopen("https://software.ultimaker.com/latest.json")
>>> import ssl
>>> c = ssl.SSLContext(ssl.PROTOCOL_TLSv1_2)
>>> len(c.get_ca_certs())
0
>>> c.load_default_certs()
>>> len(c.get_ca_certs())
67
>>>
bvalat commented 5 years ago

Maybe you have found a lead for me. Python 3.5.2 is crahsing silently but not 3.5.4 (And when i ran it from code it was with 3.5.4). Here is 3.5.2 :

C:\py>python.exe
Python 3.5.2 (v3.5.2:4def2a2901a5, Jun 25 2016, 22:18:55) [MSC v.1900 64 bit (AMD64)] on win32
Type "help", "copyright", "credits" or "license" for more information.
>>> import urllib.request
>>> f = urllib.request.urlopen("https://software.ultimaker.com/latest.json")

C:\py>
C:\py>echo %errorlevel%
-1073741819
C:\pi354>python.exe
Python 3.5.4 (v3.5.4:3f56838, Aug  8 2017, 02:17:05) [MSC v.1900 64 bit (AMD64)] on win32
Type "help", "copyright", "credits" or "license" for more information.
>>> import urllib.request
>>> f = urllib.request.urlopen("https://software.ultimaker.com/latest.json")
>>> print(f.read().decode('utf-8'))
{
    "cura": {
        "Windows": {
            "major": 4,
            "minor": 2,
            "revision": 1,
            "url": "https://ultimaker.com/en/products/ultimaker-cura-software?utm_source=cura&utm_medium=software&utm_campaign=sw-update"
        },
        "Linux": {
            "major": 4,
            "minor": 2,
            "revision": 1,
            "url": "https://ultimaker.com/en/products/ultimaker-cura-software?utm_source=cura&utm_medium=software&utm_campaign=sw-update"
        },
        "Darwin": {
            "major": 4,
            "minor": 2,
            "revision": 1,
            "url": "https://ultimaker.com/en/products/ultimaker-cura-software?utm_source=cura&utm_medium=software&utm_campaign=sw-update"
        }
bvalat commented 5 years ago

YES!!!!!! I replaced _ssl.pyd by the one of 3.5.4 https://www.python.org/ftp/python/3.5.4/python-3.5.4-embed-amd64.zip and everything works for me. Even my old unresolved #5817

Maybe it's time to update python version embedded in cura? yes i know, easier to say, harder to do but i think a least 3.5.4 should be not too painful.

LipuFei commented 5 years ago

No errors for me. But again Cura wont start...

@Routout Could you upload your log file? You can find it in C:\Users\<your-user-name>\AppData\Roaming\cura\4.2\

Ghostkeeper commented 5 years ago

There can hardly be a safer time to update our dependencies than this, with the last release just out the next release is far away.

LipuFei commented 5 years ago

YES!!!!!! I replaced _ssl.pyd by the one of 3.5.4 https://www.python.org/ftp/python/3.5.4/python-3.5.4-embed-amd64.zip and everything works for me. Even my old unresolved #5817

Maybe it's time to update python version embedded in cura? yes i know, easier to say, harder to do but i think a least 3.5.4 should be not too painful.

@bvalat Glad that you found a solution! Thank you very much for the information!

I compared the bundled OpenSSL versions in Python 3.5 for Windows:

There's indeed a difference in which OpenSSL they use.

I also tested both python 3.5.2 and 3.5.4 with the embedded ZIPs from python.org on a clean Windows Server 2019. They both give the CERTIFICATE_VERIFY_FAILED error message in my case. You can find an example error below. So, I think your silent crash is something related to the OpenSSL version that's being used, but not the CA certificates. As described in python issue 36011, if you get the CA certificate issue once, you will keep getting it until the necessary CA certificates are imported into the Windows certificate store.

>>> import urllib.request
>>> f = urllib.request.urlopen("https://software.ultimaker.com/latest.json")
Traceback (most recent call last):
  File "urllib\request.py", line 1254, in do_open
  File "http\client.py", line 1107, in request
  File "http\client.py", line 1152, in _send_request
  File "http\client.py", line 1103, in endheaders
  File "http\client.py", line 934, in _send_output
  File "http\client.py", line 877, in send
  File "http\client.py", line 1261, in connect
  File "ssl.py", line 385, in wrap_socket
  File "ssl.py", line 760, in __init__
  File "ssl.py", line 996, in do_handshake
  File "ssl.py", line 641, in do_handshake
ssl.SSLError: [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed (_ssl.c:719)

We will discuss the Python upgrade. ~If I remember it correctly, upgrading to 3.5.4+ was not so easy with our current build system... 3.5.4+ requires VS2017 while we only have VS2015 in the system. It will take more effort than just changing the version we use.~

EDIT: I just tried to create a build environment with Python 3.5.7 and turns out it doesn't need VS2017 on Windows. The processes on Mac and Linux are still running. Let's hope there will be no problem and then we can start testing it.

Routout commented 5 years ago

No errors for me. But again Cura wont start...

@Routout Could you upload your log file? You can find it in C:\Users\<your-user-name>\AppData\Roaming\cura\4.2\

2019-08-13 10:58:02,484 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin FileLogger
2019-08-13 10:58:02,499 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin FirmwareUpdateChecker
2019-08-13 10:58:02,511 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin FirmwareUpdater
2019-08-13 10:58:02,522 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin GCodeGzReader
2019-08-13 10:58:02,534 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin GCodeGzWriter
2019-08-13 10:58:02,545 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin GCodeProfileReader
2019-08-13 10:58:02,567 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin GCodeReader
2019-08-13 10:58:02,580 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin GCodeWriter
2019-08-13 10:58:02,595 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin ImageReader
2019-08-13 10:58:02,607 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin LegacyProfileReader
2019-08-13 10:58:02,620 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin LocalContainerProvider
2019-08-13 10:58:02,634 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin LocalFileOutputDevice
2019-08-13 10:58:02,645 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin MachineSettingsAction
2019-08-13 10:58:02,657 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin ModelChecker
2019-08-13 10:58:02,670 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin MonitorStage
2019-08-13 10:58:02,683 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin PerObjectSettingsTool
2019-08-13 10:58:02,696 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin PostProcessingPlugin
2019-08-13 10:58:02,708 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin PrepareStage
2019-08-13 10:58:02,720 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin PreviewStage
2019-08-13 10:58:02,742 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin RemovableDriveOutputDevice
2019-08-13 10:58:02,766 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin SimulationView
2019-08-13 10:58:02,783 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin SliceInfoPlugin
2019-08-13 10:58:02,797 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin SolidView
2019-08-13 10:58:02,811 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin SupportEraser
2019-08-13 10:58:02,834 - DEBUG - [MainThread] cura.OAuth2.AuthorizationService.getAccessToken [112]: No auth data to retrieve the access_token from
2019-08-13 10:58:02,838 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin Toolbox
2019-08-13 10:58:02,853 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin CameraTool
2019-08-13 10:58:02,869 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin MirrorTool
2019-08-13 10:58:02,886 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin RotateTool
2019-08-13 10:58:02,903 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin ScaleTool
2019-08-13 10:58:02,915 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin SelectionTool
2019-08-13 10:58:02,933 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin TranslateTool
2019-08-13 10:58:02,979 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin UFPReader
2019-08-13 10:58:02,994 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin UFPWriter
2019-08-13 10:58:03,011 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin UltimakerMachineActions
2019-08-13 10:58:03,121 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin UM3NetworkPrinting
2019-08-13 10:58:03,143 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin UpdateChecker
2019-08-13 10:58:03,146 - INFO - [Thread-1] UpdateChecker.UpdateCheckerJob.run [36]: Checking for new version of cura
2019-08-13 10:58:03,486 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin USBPrinting
2019-08-13 10:58:03,654 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin VersionUpgrade21to22
2019-08-13 10:58:03,722 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin VersionUpgrade22to24
2019-08-13 10:58:03,790 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin VersionUpgrade25to26
2019-08-13 10:58:03,866 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin VersionUpgrade26to27
2019-08-13 10:58:03,941 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin VersionUpgrade27to30
2019-08-13 10:58:04,015 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin VersionUpgrade30to31
2019-08-13 10:58:04,080 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin VersionUpgrade32to33
2019-08-13 10:58:04,128 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin VersionUpgrade33to34
2019-08-13 10:58:04,158 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin VersionUpgrade34to35
2019-08-13 10:58:04,183 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin VersionUpgrade35to40
2019-08-13 10:58:04,209 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin VersionUpgrade40to41
2019-08-13 10:58:04,234 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin VersionUpgrade41to42
2019-08-13 10:58:04,258 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin SimpleView
2019-08-13 10:58:04,282 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin X3DReader
2019-08-13 10:58:04,307 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin XmlMaterialProfile
2019-08-13 10:58:04,325 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin XRayView
2019-08-13 10:58:04,351 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [405]: Loaded plugin OctoPrintPlugin
2019-08-13 10:58:04,368 - INFO - [MainThread] UM.VersionUpgradeManager.upgrade [145]: Looking for old configuration files to upgrade.
2019-08-13 10:58:04,396 - WARNING - [MainThread] UM.VersionUpgradeManager._getUpgradeTasks [306]: Failed to get file version: .\packages.json, skip it
2019-08-13 10:58:04,399 - WARNING - [MainThread] UM.VersionUpgradeManager._getUpgradeTasks [306]: Failed to get file version: .\plugins.json, skip it
2019-08-13 10:58:04,403 - WARNING - [MainThread] UM.VersionUpgradeManager._getUpgradeTasks [306]: Failed to get file version: .\packages.json, skip it
2019-08-13 10:58:04,407 - WARNING - [MainThread] UM.VersionUpgradeManager._getUpgradeTasks [306]: Failed to get file version: .\plugins.json, skip it
2019-08-13 10:58:04,411 - WARNING - [MainThread] UM.VersionUpgradeManager._getUpgradeTasks [306]: Failed to get file version: .\packages.json, skip it
2019-08-13 10:58:04,415 - WARNING - [MainThread] UM.VersionUpgradeManager._getUpgradeTasks [306]: Failed to get file version: .\plugins.json, skip it
2019-08-13 10:58:04,419 - WARNING - [MainThread] UM.VersionUpgradeManager._getUpgradeTasks [306]: Failed to get file version: .\packages.json, skip it
2019-08-13 10:58:04,422 - WARNING - [MainThread] UM.VersionUpgradeManager._getUpgradeTasks [306]: Failed to get file version: .\plugins.json, skip it
2019-08-13 10:58:04,426 - WARNING - [MainThread] UM.VersionUpgradeManager._getUpgradeTasks [306]: Failed to get file version: .\packages.json, skip it
2019-08-13 10:58:04,429 - WARNING - [MainThread] UM.VersionUpgradeManager._getUpgradeTasks [306]: Failed to get file version: .\plugins.json, skip it
2019-08-13 10:58:04,433 - WARNING - [MainThread] UM.VersionUpgradeManager._getUpgradeTasks [306]: Failed to get file version: .\packages.json, skip it
2019-08-13 10:58:04,436 - WARNING - [MainThread] UM.VersionUpgradeManager._getUpgradeTasks [306]: Failed to get file version: .\plugins.json, skip it
2019-08-13 10:58:04,440 - WARNING - [MainThread] UM.VersionUpgradeManager._getUpgradeTasks [306]: Failed to get file version: .\packages.json, skip it
2019-08-13 10:58:04,443 - WARNING - [MainThread] UM.VersionUpgradeManager._getUpgradeTasks [306]: Failed to get file version: .\plugins.json, skip it
2019-08-13 10:58:04,449 - WARNING - [MainThread] UM.VersionUpgradeManager._getUpgradeTasks [306]: Failed to get file version: .\packages.json, skip it
2019-08-13 10:58:04,452 - WARNING - [MainThread] UM.VersionUpgradeManager._getUpgradeTasks [306]: Failed to get file version: .\plugins.json, skip it
2019-08-13 10:58:04,456 - WARNING - [MainThread] UM.VersionUpgradeManager._getUpgradeTasks [306]: Failed to get file version: .\packages.json, skip it
2019-08-13 10:58:04,459 - WARNING - [MainThread] UM.VersionUpgradeManager._getUpgradeTasks [306]: Failed to get file version: .\plugins.json, skip it
2019-08-13 10:58:04,463 - WARNING - [MainThread] UM.VersionUpgradeManager._getUpgradeTasks [306]: Failed to get file version: .\packages.json, skip it
2019-08-13 10:58:04,465 - WARNING - [MainThread] UM.VersionUpgradeManager._getUpgradeTasks [306]: Failed to get file version: .\plugins.json, skip it
2019-08-13 10:58:04,478 - WARNING - [MainThread] UM.VersionUpgradeManager._getUpgradeTasks [306]: Failed to get file version: ..\generic_petg_175+%232.xml.fdm_material, skip it
2019-08-13 10:58:04,481 - WARNING - [MainThread] UM.VersionUpgradeManager._getUpgradeTasks [306]: Failed to get file version: ..\generic_pla_175+%232.xml.fdm_material, skip it
2019-08-13 10:58:04,502 - DEBUG - [MainThread] UM.Backend.Backend._onSocketError [197]: Socket was unable to bind to port, increasing port number to 49675
2019-08-13 10:58:04,505 - DEBUG - [MainThread] UM.Backend.Backend._createSocket [211]: Previous socket existed. Closing that first.
2019-08-13 10:58:04,507 - DEBUG - [MainThread] CuraEngineBackend.CuraEngineBackend._terminate [292]: Attempting to kill the engine process
2019-08-13 10:58:04,509 - DEBUG - [MainThread] UM.Backend.Backend._createSocket [211]: Previous socket existed. Closing that first.
2019-08-13 10:58:04,636 - DEBUG - [MainThread] UM.Backend.Backend._logSocketState [171]: Socket state changed to Listening
2019-08-13 10:58:04,647 - INFO - [MainThread] UM.Backend.Backend.startEngine [81]: Started engine process: C:\Program Files\Ultimaker Cura 4.2\CuraEngine.exe
2019-08-13 10:58:04,654 - DEBUG - [MainThread] UM.Backend.Backend._backendLog [101]: [Backend] Calling engine with: ['C:\\Program Files\\Ultimaker Cura 4.2\\CuraEngine.exe', 'connect', '127.0.0.1:49675', '']
2019-08-13 10:58:04,708 - DEBUG - [Thread-12] UM.Backend.Backend._backendLog [101]: [Backend] 
2019-08-13 10:58:04,711 - DEBUG - [Thread-12] UM.Backend.Backend._backendLog [101]: [Backend] Cura_SteamEngine version 4.2.1
2019-08-13 10:58:04,714 - DEBUG - [Thread-12] UM.Backend.Backend._backendLog [101]: [Backend] Copyright (C) 2018 Ultimaker
2019-08-13 10:58:04,716 - DEBUG - [Thread-12] UM.Backend.Backend._backendLog [101]: [Backend] 
2019-08-13 10:58:04,719 - DEBUG - [Thread-12] UM.Backend.Backend._backendLog [101]: [Backend] This program is free software: you can redistribute it and/or modify
2019-08-13 10:58:04,721 - DEBUG - [Thread-12] UM.Backend.Backend._backendLog [101]: [Backend] it under the terms of the GNU Affero General Public License as published by
2019-08-13 10:58:04,723 - DEBUG - [Thread-12] UM.Backend.Backend._backendLog [101]: [Backend] the Free Software Foundation, either version 3 of the License, or
2019-08-13 10:58:04,726 - DEBUG - [Thread-12] UM.Backend.Backend._backendLog [101]: [Backend] (at your option) any later version.
2019-08-13 10:58:04,732 - DEBUG - [Thread-12] UM.Backend.Backend._backendLog [101]: [Backend] 
2019-08-13 10:58:04,738 - DEBUG - [Thread-12] UM.Backend.Backend._backendLog [101]: [Backend] This program is distributed in the hope that it will be useful,
2019-08-13 10:58:04,740 - DEBUG - [Thread-12] UM.Backend.Backend._backendLog [101]: [Backend] but WITHOUT ANY WARRANTY; without even the implied warranty of
2019-08-13 10:58:04,743 - DEBUG - [Thread-12] UM.Backend.Backend._backendLog [101]: [Backend] MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
2019-08-13 10:58:04,746 - DEBUG - [Thread-12] UM.Backend.Backend._backendLog [101]: [Backend] GNU Affero General Public License for more details.
2019-08-13 10:58:04,748 - DEBUG - [Thread-12] UM.Backend.Backend._backendLog [101]: [Backend] 
2019-08-13 10:58:04,751 - DEBUG - [Thread-12] UM.Backend.Backend._backendLog [101]: [Backend] You should have received a copy of the GNU Affero General Public License
2019-08-13 10:58:04,753 - DEBUG - [Thread-12] UM.Backend.Backend._backendLog [101]: [Backend] along with this program.  If not, see <http://www.gnu.org/licenses/>.
2019-08-13 10:58:04,867 - DEBUG - [MainThread] UM.Backend.Backend._logSocketState [175]: Socket state changed to Connected
2019-08-13 10:58:04,869 - DEBUG - [MainThread] UM.Backend.Backend._onSocketStateChanged [165]: Backend connected on port 49675
2019-08-13 10:58:07,353 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.loadAllMetadata [339]: Loading metadata into container registry took 2.6928369998931885 seconds
2019-08-13 10:58:07,449 - DEBUG - [MainThread] cura.Scene.CuraSceneController.setActiveBuildPlate [104]: Select build plate: 0
2019-08-13 10:58:07,455 - INFO - [MainThread] cura.CuraApplication.run [728]: Initializing variant manager
2019-08-13 10:58:07,462 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container ultimaker_s5_aluminum
2019-08-13 10:58:07,467 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [ultimaker_s5_aluminum] added.
2019-08-13 10:58:07,467 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container ultimaker_s5
2019-08-13 10:58:07,514 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [ultimaker_s5] added.
2019-08-13 10:58:07,516 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container ultimaker_s5_glass
2019-08-13 10:58:07,521 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [ultimaker_s5_glass] added.
2019-08-13 10:58:07,525 - DEBUG - [MainThread] cura.Machines.VariantManager.initialize [59]: Exclude variant [empty_variant]
2019-08-13 10:58:07,526 - INFO - [MainThread] cura.CuraApplication.run [732]: Initializing material manager
2019-08-13 10:58:07,585 - INFO - [MainThread] cura.CuraApplication.run [737]: Initializing quality manager
2019-08-13 10:58:07,613 - DEBUG - [MainThread] cura.Machines.QualityManager.initialize [136]: Lookup tables updated.
2019-08-13 10:58:07,617 - INFO - [MainThread] cura.CuraApplication.run [742]: Initializing machine manager
2019-08-13 10:58:07,622 - INFO - [MainThread] cura.CuraApplication.run [745]: Initializing container manager
2019-08-13 10:58:07,625 - INFO - [MainThread] cura.CuraApplication.run [748]: Initializing machine error checker
2019-08-13 10:58:07,774 - DEBUG - [MainThread] UM3NetworkPrinting.src.Cloud.CloudOutputDeviceManager._onLoginStateChanged [57]: Log in state changed to False
2019-08-13 10:58:07,775 - DEBUG - [MainThread] UM3NetworkPrinting.src.Cloud.CloudOutputDeviceManager._onGetRemoteClustersFinished [80]: Parsed remote clusters to []
2019-08-13 10:58:07,776 - DEBUG - [MainThread] UM3NetworkPrinting.src.Cloud.CloudOutputDeviceManager._onGetRemoteClustersFinished [81]: Removed: 0, added: 0, updates: 0
2019-08-13 10:58:07,915 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container Creality Ender-3
2019-08-13 10:58:07,917 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container Creality Ender-3_user
2019-08-13 10:58:07,922 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [Creality Ender-3_user] added.
2019-08-13 10:58:07,923 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container creality_ender3_oma_-_standard_quality
2019-08-13 10:58:07,928 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [creality_ender3_oma_-_standard_quality] added.
2019-08-13 10:58:07,929 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container base_global_standard
2019-08-13 10:58:07,934 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [base_global_standard] added.
2019-08-13 10:58:07,935 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container Creality Ender-3_settings
2019-08-13 10:58:07,940 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [Creality Ender-3_settings] added.
2019-08-13 10:58:07,940 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container creality_ender3
2019-08-13 10:58:08,029 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [creality_ender3] added.
2019-08-13 10:58:08,034 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [Creality Ender-3] added.
2019-08-13 10:58:08,036 - INFO - [MainThread] cura.UI.MachineActionManager.addDefaultMachineActions [72]: Default machine actions added for machine definition [creality_ender3]
2019-08-13 10:58:08,040 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container creality_base_extruder_0 #2
2019-08-13 10:58:08,043 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container creality_base_extruder_0 #2_user
2019-08-13 10:58:08,047 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [creality_base_extruder_0 #2_user] added.
2019-08-13 10:58:08,048 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container creality_base_extruder_0_#2_oma_-_standard_quality
2019-08-13 10:58:08,052 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [creality_base_extruder_0_#2_oma_-_standard_quality] added.
2019-08-13 10:58:08,053 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container base_0.4_PETG_standard
2019-08-13 10:58:08,057 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [base_0.4_PETG_standard] added.
2019-08-13 10:58:08,057 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container generic_petg_175 #2
2019-08-13 10:58:08,070 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [generic_petg_175 #2_creality_ender5] added.
2019-08-13 10:58:08,072 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [generic_petg_175 #2_creality_cr10] added.
2019-08-13 10:58:08,075 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [generic_petg_175 #2_creality_cr10s] added.
2019-08-13 10:58:08,077 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [generic_petg_175 #2_creality_ender3] added.
2019-08-13 10:58:08,080 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [generic_petg_175 #2_creality_base] added.
2019-08-13 10:58:08,082 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [generic_petg_175 #2_creality_cr10s4] added.
2019-08-13 10:58:08,084 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [generic_petg_175 #2_creality_cr10spro] added.
2019-08-13 10:58:08,086 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [generic_petg_175 #2_creality_ender2] added.
2019-08-13 10:58:08,089 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [generic_petg_175 #2_creality_ender4] added.
2019-08-13 10:58:08,091 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [generic_petg_175 #2_creality_cr10s5] added.
2019-08-13 10:58:08,093 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [generic_petg_175 #2_creality_cr20] added.
2019-08-13 10:58:08,096 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [generic_petg_175 #2_cartesio] added.
2019-08-13 10:58:08,098 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [generic_petg_175 #2_cartesio_0.8mm_thermoplastic_extruder] added.
2019-08-13 10:58:08,100 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [generic_petg_175 #2_cartesio_0.25mm_thermoplastic_extruder] added.
2019-08-13 10:58:08,102 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [generic_petg_175 #2_cartesio_0.4mm_thermoplastic_extruder] added.
2019-08-13 10:58:08,105 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [generic_petg_175 #2_creality_cr20pro] added.
2019-08-13 10:58:08,109 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [generic_petg_175 #2_imade3d_jellybox] added.
2019-08-13 10:58:08,111 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [generic_petg_175 #2_imade3d_jellybox_0.4_mm] added.
2019-08-13 10:58:08,114 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [generic_petg_175 #2_imade3d_jellybox_0.4_mm_2-fans] added.
2019-08-13 10:58:08,117 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [generic_petg_175 #2_creality_cr10mini] added.
2019-08-13 10:58:08,120 - WARNING - [MainThread] UM.Settings.ContainerRegistry.addContainer [376]: Container with ID generic_petg_175 #2_creality_ender3 was already added.
2019-08-13 10:58:08,120 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container creality_ender3_0.4
2019-08-13 10:58:08,124 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [creality_ender3_0.4] added.
2019-08-13 10:58:08,125 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container creality_base_extruder_0 #2_settings
2019-08-13 10:58:08,129 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [creality_base_extruder_0 #2_settings] added.
2019-08-13 10:58:08,130 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container creality_base_extruder_0
2019-08-13 10:58:08,134 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [creality_base_extruder_0] added.
2019-08-13 10:58:08,137 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [creality_base_extruder_0 #2] added.
2019-08-13 10:58:08,224 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container creality_base
2019-08-13 10:58:08,268 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [creality_base] added.
2019-08-13 10:58:08,517 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [170]: Begin loading of script: BQ_PauseAtHeight
2019-08-13 10:58:08,521 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [170]: Begin loading of script: ChangeAtZ
2019-08-13 10:58:08,522 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [170]: Begin loading of script: DisplayFilenameAndLayerOnLCD
2019-08-13 10:58:08,524 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [170]: Begin loading of script: FilamentChange
2019-08-13 10:58:08,525 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [170]: Begin loading of script: InsertAtLayerChange
2019-08-13 10:58:08,528 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [170]: Begin loading of script: PauseAtHeight
2019-08-13 10:58:08,530 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [170]: Begin loading of script: PauseAtHeightRepRapFirmwareDuet
2019-08-13 10:58:08,531 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [170]: Begin loading of script: PauseAtHeightforRepetier
2019-08-13 10:58:08,533 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [170]: Begin loading of script: SearchAndReplace
2019-08-13 10:58:08,537 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [170]: Begin loading of script: Stretch
2019-08-13 10:58:08,538 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [170]: Begin loading of script: TimeLapse
2019-08-13 10:58:08,539 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin.loadScripts [170]: Begin loading of script: UsePreviousProbeMeasurements
2019-08-13 10:58:08,540 - DEBUG - [MainThread] UM3NetworkPrinting.src.UM3OutputDevicePlugin.checkCloudFlowIsPossible [511]: Checking if cloud connection is possible...
2019-08-13 10:58:08,541 - DEBUG - [MainThread] UM3NetworkPrinting.src.UM3OutputDevicePlugin.checkCloudFlowIsPossible [533]: Cloud Flow not possible: User not logged in!
2019-08-13 10:58:08,545 - DEBUG - [MainThread] cura.PrinterOutput.NetworkedPrinterOutputDevice._createNetworkManager [313]: Creating network manager
2019-08-13 10:58:08,553 - DEBUG - [MainThread] OctoPrintPlugin.OctoPrintOutputDevice.connect [296]: Connection with instance octopi with url http://192.168.1.6:80/ started
2019-08-13 10:58:08,679 - INFO - [MainThread] cura.Settings.GlobalStack.addExtruder [161]: Extruder[creality_base_extruder_0 #2] added to [Creality Ender-3] at position [0]
2019-08-13 10:58:08,681 - WARNING - [MainThread] cura.Settings.ExtruderManager.registerExtruder [169]: Extruder [creality_base_extruder_0 #2] has already been registered on machine [Creality Ender-3], not doing anything
2019-08-13 10:58:08,754 - DEBUG - [MainThread] cura.Machines.MaterialManager.getAvailableMaterials [361]: Exclude materials verbatim_bvoh_175, fabtotum_pla, Vertex_Delta_PET, imade3d_pla_green, imade3d_pla_pink, octofiber_pla, filo3d_pla_red, tizyx_abs, fabtotum_tpu, Vertex_Delta_PLA, filo3d_pla, polyplus_pla, imade3d_petg_pink, fabtotum_abs, chromatik_pla, imade3d_petg_green, dsm_novamid1070_175, zyyx_pro_pla, polymax_pla, innofill_innoflex60_175, Vertex_Delta_TPU, fabtotum_nylon, tizyx_pla_bois, zyyx_pro_flex, dsm_arnitel2045_175, polyflex_pla, tizyx_pla, polywood_pla, fiberlogy_hd_pla, filo3d_pla_green, Vertex_Delta_ABS for machine creality_ender3
2019-08-13 10:58:08,761 - INFO - [MainThread] cura.Settings.MachineManager._initMachineState [323]: Machine 'Creality Ender-3' quality changes set to 'Oma - Standard Quality'
2019-08-13 10:58:08,909 - WARNING - [MainThread] UM.Settings.InstanceContainer.setProperty [333]: Tried to set value of setting #retraction_extra_prime_amount that has no instance in container Standard Quality or its definition Creawsome Base Printer
2019-08-13 10:58:08,918 - INFO - [MainThread] FirmwareUpdateChecker.FirmwareUpdateChecker.checkFirmwareVersion [74]: No machine with name Creality Ender-3 in list of firmware to check.
2019-08-13 10:58:08,928 - INFO - [MainThread] UM.OutputDevice.OutputDeviceManager.addOutputDevice [156]: Output Device octopi already added
2019-08-13 10:58:08,929 - DEBUG - [MainThread] OctoPrintPlugin.OctoPrintOutputDevice._onRequestFinished [707]: Set OctoPrint camera url to http://192.168.1.6/webcam/?action=stream
2019-08-13 10:58:08,950 - DEBUG - [MainThread] UM.Scene.Camera._preferencesChanged [233]: Changing perspective mode to perspective.
2019-08-13 10:58:09,705 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin._createView [281]: Creating post processing plugin view.
2019-08-13 10:58:09,776 - DEBUG - [MainThread] UM.Qt.Bindings.Theme.load [158]: Loading theme file: C:\Program Files\Ultimaker Cura 4.2\resources\themes\cura-light\theme.json
2019-08-13 10:58:09,904 - DEBUG - [MainThread] UM.Qt.Bindings.Theme.load [231]: Loaded theme C:\Program Files\Ultimaker Cura 4.2\resources\themes\cura-light
2019-08-13 10:58:10,663 - DEBUG - [MainThread] PostProcessingPlugin.PostProcessingPlugin._createView [291]: Post processing view created.
2019-08-13 10:58:10,791 - DEBUG - [MainThread] cura.OAuth2.AuthorizationService._parseJWT [89]: There was no auth data or access token
2019-08-13 10:58:10,793 - DEBUG - [MainThread] cura.OAuth2.AuthorizationService._parseJWT [89]: There was no auth data or access token
2019-08-13 10:58:10,797 - DEBUG - [MainThread] cura.OAuth2.AuthorizationService._parseJWT [89]: There was no auth data or access token
2019-08-13 10:58:10,800 - WARNING - [MainThread] UM.Qt.Bindings.Theme.getImage [133]: No image header_pattern defined in Theme
2019-08-13 10:58:10,809 - WARNING - [MainThread] UM.Decorators.deprecated_function [19]: <function MachineManager.currentExtruderPositions at 0x0000026A10E17840> is deprecated (since 4.2): use Cura.MachineManager.activeMachine.extruders instead
2019-08-13 10:58:10,812 - WARNING - [MainThread] UM.Decorators.deprecated_function [19]: <function MachineManager.hasVariantBuildplates at 0x0000026A10E14730> is deprecated (since 4.2): use Cura.MachineManager.activeMachine.hasVariantBuildplates instead
2019-08-13 10:58:10,816 - DEBUG - [MainThread] cura.Machines.Models.BuildPlateModel._update [33]: Updating BuildPlateModel.
2019-08-13 10:58:11,515 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [369]: file:///C:/Program Files/Ultimaker Cura 4.2/qml/QtQuick/Controls/Private/BasicTableView.qml:613:17: QML QQuickItem*: Binding loop detected for property "width"
2019-08-13 10:58:12,365 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [369]: file:///C:/Program Files/Ultimaker Cura 4.2/resources/qml/IconWithText.qml:51:5: QML Label: Binding loop detected for property "text"
2019-08-13 10:58:12,437 - WARNING - [MainThread] UM.Decorators.deprecated_function [19]: <function MachineManager._getExtruder at 0x0000026A10E14D90> is deprecated (since 4.2): use Cura.MachineManager.activeMachine.extruders instead
2019-08-13 10:58:12,602 - DEBUG - [MainThread] UM3NetworkPrinting.src.DiscoverUM3Action._createAdditionalComponentsView [166]: Creating additional ui components for UM3.
2019-08-13 10:58:12,646 - DEBUG - [MainThread] UM3NetworkPrinting.src.DiscoverUM3Action.startDiscovery [52]: Starting device discovery.
2019-08-13 10:58:12,649 - DEBUG - [MainThread] OctoPrintPlugin.DiscoverOctoPrintAction._createAdditionalComponentsView [341]: Creating additional ui components for OctoPrint-connected printers.
2019-08-13 10:58:12,686 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [369]: file:///C:/Program Files/Ultimaker Cura 4.2/qml/QtQuick/Controls/Button.qml:99: TypeError: Cannot read property of null
2019-08-13 10:58:12,688 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [369]: file:///C:/Users/Sami/AppData/Roaming/cura/4.2/plugins/OctoPrintPlugin/OctoPrintPlugin/OctoPrintComponents.qml:25:16: Unable to assign [undefined] to QQmlComponent*
2019-08-13 10:58:12,692 - DEBUG - [MainThread] UM.Controller.setActiveStage [149]: Setting active stage to PrepareStage
2019-08-13 10:58:12,790 - DEBUG - [MainThread] cura.Machines.MaterialManager.getAvailableMaterials [361]: Exclude materials verbatim_bvoh_175, fabtotum_pla, Vertex_Delta_PET, imade3d_pla_green, imade3d_pla_pink, octofiber_pla, filo3d_pla_red, tizyx_abs, fabtotum_tpu, Vertex_Delta_PLA, filo3d_pla, polyplus_pla, imade3d_petg_pink, fabtotum_abs, chromatik_pla, imade3d_petg_green, dsm_novamid1070_175, zyyx_pro_pla, polymax_pla, innofill_innoflex60_175, Vertex_Delta_TPU, fabtotum_nylon, tizyx_pla_bois, zyyx_pro_flex, dsm_arnitel2045_175, polyflex_pla, tizyx_pla, polywood_pla, fiberlogy_hd_pla, filo3d_pla_green, Vertex_Delta_ABS for machine creality_ender3
2019-08-13 10:58:12,800 - DEBUG - [MainThread] cura.Machines.MaterialManager.getAvailableMaterials [361]: Exclude materials verbatim_bvoh_175, fabtotum_pla, Vertex_Delta_PET, imade3d_pla_green, imade3d_pla_pink, octofiber_pla, filo3d_pla_red, tizyx_abs, fabtotum_tpu, Vertex_Delta_PLA, filo3d_pla, polyplus_pla, imade3d_petg_pink, fabtotum_abs, chromatik_pla, imade3d_petg_green, dsm_novamid1070_175, zyyx_pro_pla, polymax_pla, innofill_innoflex60_175, Vertex_Delta_TPU, fabtotum_nylon, tizyx_pla_bois, zyyx_pro_flex, dsm_arnitel2045_175, polyflex_pla, tizyx_pla, polywood_pla, fiberlogy_hd_pla, filo3d_pla_green, Vertex_Delta_ABS for machine creality_ender3
2019-08-13 10:58:12,809 - DEBUG - [MainThread] cura.Machines.MaterialManager.getAvailableMaterials [361]: Exclude materials verbatim_bvoh_175, fabtotum_pla, Vertex_Delta_PET, imade3d_pla_green, imade3d_pla_pink, octofiber_pla, filo3d_pla_red, tizyx_abs, fabtotum_tpu, Vertex_Delta_PLA, filo3d_pla, polyplus_pla, imade3d_petg_pink, fabtotum_abs, chromatik_pla, imade3d_petg_green, dsm_novamid1070_175, zyyx_pro_pla, polymax_pla, innofill_innoflex60_175, Vertex_Delta_TPU, fabtotum_nylon, tizyx_pla_bois, zyyx_pro_flex, dsm_arnitel2045_175, polyflex_pla, tizyx_pla, polywood_pla, fiberlogy_hd_pla, filo3d_pla_green, Vertex_Delta_ABS for machine creality_ender3
2019-08-13 10:58:12,815 - DEBUG - [MainThread] cura.Machines.Models.NozzleModel._update [34]: Updating NozzleModel.
2019-08-13 10:58:12,821 - WARNING - [MainThread] UM.Decorators.deprecated_function [19]: <function MachineManager.activeMachineHasRemoteConnection at 0x0000026A10E10048> is deprecated (since 4.2): use Cura.MachineManager.activeMachine.configuredConnectionTypes instead
2019-08-13 10:58:12,828 - WARNING - [MainThread] UM.Decorators.deprecated_function [19]: <function MachineManager.hasMaterials at 0x0000026A10E14510> is deprecated (since 4.2): use Cura.MachineManager.activeMachine.hasMaterials instead
2019-08-13 10:58:12,836 - WARNING - [MainThread] UM.Decorators.deprecated_function [19]: <function MachineManager.hasVariants at 0x0000026A10E14620> is deprecated (since 4.2): use Cura.MachineManager.activeMachine.hasVariants instead
2019-08-13 10:58:12,853 - DEBUG - [MainThread] cura.Machines.MaterialManager.getAvailableMaterials [361]: Exclude materials verbatim_bvoh_175, fabtotum_pla, Vertex_Delta_PET, imade3d_pla_green, imade3d_pla_pink, octofiber_pla, filo3d_pla_red, tizyx_abs, fabtotum_tpu, Vertex_Delta_PLA, filo3d_pla, polyplus_pla, imade3d_petg_pink, fabtotum_abs, chromatik_pla, imade3d_petg_green, dsm_novamid1070_175, zyyx_pro_pla, polymax_pla, innofill_innoflex60_175, Vertex_Delta_TPU, fabtotum_nylon, tizyx_pla_bois, zyyx_pro_flex, dsm_arnitel2045_175, polyflex_pla, tizyx_pla, polywood_pla, fiberlogy_hd_pla, filo3d_pla_green, Vertex_Delta_ABS for machine creality_ender3
2019-08-13 10:58:12,858 - DEBUG - [MainThread] cura.Machines.MaterialManager.getAvailableMaterials [361]: Exclude materials verbatim_bvoh_175, fabtotum_pla, Vertex_Delta_PET, imade3d_pla_green, imade3d_pla_pink, octofiber_pla, filo3d_pla_red, tizyx_abs, fabtotum_tpu, Vertex_Delta_PLA, filo3d_pla, polyplus_pla, imade3d_petg_pink, fabtotum_abs, chromatik_pla, imade3d_petg_green, dsm_novamid1070_175, zyyx_pro_pla, polymax_pla, innofill_innoflex60_175, Vertex_Delta_TPU, fabtotum_nylon, tizyx_pla_bois, zyyx_pro_flex, dsm_arnitel2045_175, polyflex_pla, tizyx_pla, polywood_pla, fiberlogy_hd_pla, filo3d_pla_green, Vertex_Delta_ABS for machine creality_ender3
2019-08-13 10:58:12,862 - DEBUG - [MainThread] cura.Machines.MaterialManager.getAvailableMaterials [361]: Exclude materials verbatim_bvoh_175, fabtotum_pla, Vertex_Delta_PET, imade3d_pla_green, imade3d_pla_pink, octofiber_pla, filo3d_pla_red, tizyx_abs, fabtotum_tpu, Vertex_Delta_PLA, filo3d_pla, polyplus_pla, imade3d_petg_pink, fabtotum_abs, chromatik_pla, imade3d_petg_green, dsm_novamid1070_175, zyyx_pro_pla, polymax_pla, innofill_innoflex60_175, Vertex_Delta_TPU, fabtotum_nylon, tizyx_pla_bois, zyyx_pro_flex, dsm_arnitel2045_175, polyflex_pla, tizyx_pla, polywood_pla, fiberlogy_hd_pla, filo3d_pla_green, Vertex_Delta_ABS for machine creality_ender3
2019-08-13 10:58:12,938 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [369]: file:///C:/Program Files/Ultimaker Cura 4.2/resources/qml/ActionButton.qml:79:9: QML Label: Binding loop detected for property "width"
2019-08-13 10:58:12,943 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [369]: file:///C:/Program Files/Ultimaker Cura 4.2/resources/qml/ActionButton.qml:79:9: QML Label: Binding loop detected for property "width"
2019-08-13 10:58:12,947 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [369]: file:///C:/Program Files/Ultimaker Cura 4.2/plugins/PrepareStage/PrepareMain.qml:16:5: QML ActionPanelWidget: Binding loop detected for property "width"
2019-08-13 10:58:12,951 - DEBUG - [MainThread] UM.Controller.setActiveView [91]: Setting active view to SolidView
2019-08-13 10:58:13,056 - WARNING - [MainThread] UM.Decorators.deprecated_function [19]: <function MachineManager.activeMachineId at 0x0000026A10E0BD08> is deprecated (since 4.1): use Cura.MachineManager.activeMachine.id instead
2019-08-13 10:58:13,111 - DEBUG - [MainThread] ModelChecker.ModelChecker._createView [107]: Creating model checker view.
2019-08-13 10:58:13,118 - DEBUG - [MainThread] ModelChecker.ModelChecker._createView [116]: Model checker view created.
2019-08-13 10:58:13,119 - DEBUG - [MainThread] SliceInfoPlugin.SliceInfo._createDialog [68]: Creating dialog [MoreInfoWindow.qml]
2019-08-13 10:58:13,165 - DEBUG - [MainThread] Toolbox.src.Toolbox._makeRequestByType [529]: Requesting packages metadata from server.
2019-08-13 10:58:14,407 - DEBUG - [MainThread] Toolbox.src.Toolbox._makeRequestByType [529]: Requesting authors metadata from server.
2019-08-13 10:58:14,412 - DEBUG - [MainThread] cura.CuraApplication.run [785]: Booting Cura took 13.406294345855713 seconds
2019-08-13 10:58:14,455 - DEBUG - [MainThread] cura.Machines.MachineErrorChecker._rescheduleCheck [136]: New error check scheduled.
2019-08-13 10:58:14,457 - INFO - [MainThread] cura.Machines.MaterialManager._updateMaps [281]: Updating material lookup data ...
2019-08-13 10:58:14,500 - DEBUG - [MainThread] cura.Machines.MaterialManager.getAvailableMaterials [361]: Exclude materials verbatim_bvoh_175, fabtotum_pla, Vertex_Delta_PET, imade3d_pla_green, imade3d_pla_pink, octofiber_pla, filo3d_pla_red, tizyx_abs, fabtotum_tpu, Vertex_Delta_PLA, filo3d_pla, polyplus_pla, imade3d_petg_pink, fabtotum_abs, chromatik_pla, imade3d_petg_green, dsm_novamid1070_175, zyyx_pro_pla, polymax_pla, innofill_innoflex60_175, Vertex_Delta_TPU, fabtotum_nylon, tizyx_pla_bois, zyyx_pro_flex, dsm_arnitel2045_175, polyflex_pla, tizyx_pla, polywood_pla, fiberlogy_hd_pla, filo3d_pla_green, Vertex_Delta_ABS for machine creality_ender3
2019-08-13 10:58:14,504 - DEBUG - [MainThread] cura.Settings.MachineManager._updateQualityWithMaterial [1291]: Updating quality/quality_changes due to material change
2019-08-13 10:58:14,508 - DEBUG - [MainThread] cura.Settings.MachineManager._updateQualityWithMaterial [1298]: Current quality type = [standard]
2019-08-13 10:58:14,510 - INFO - [MainThread] cura.Settings.MachineManager._updateQualityWithMaterial [1312]: Current available quality type [standard] is available, applying changes.
2019-08-13 10:58:14,593 - DEBUG - [MainThread] cura.Machines.QualityManager.initialize [136]: Lookup tables updated.
2019-08-13 10:58:14,692 - DEBUG - [MainThread] cura.Machines.Models.QualityProfilesDropDownMenuModel._update [61]: Updating QualityProfilesDropDownMenuModel.
2019-08-13 10:58:14,694 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container base_global_adaptive
2019-08-13 10:58:14,699 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [base_global_adaptive] added.
2019-08-13 10:58:14,764 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container base_global_draft
2019-08-13 10:58:14,770 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [base_global_draft] added.
2019-08-13 10:58:14,827 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container base_global_low
2019-08-13 10:58:14,833 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [base_global_low] added.
2019-08-13 10:58:14,889 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container base_global_super
2019-08-13 10:58:14,895 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [base_global_super] added.
2019-08-13 10:58:14,967 - DEBUG - [MainThread] LocalContainerProvider.LocalContainerProvider.loadContainer [59]: Loading container base_global_ultra
2019-08-13 10:58:14,980 - DEBUG - [MainThread] UM.Settings.ContainerRegistry.addContainer [387]: Container [base_global_ultra] added.
2019-08-13 10:58:15,107 - DEBUG - [MainThread] cura.Machines.Models.CustomQualityProfilesDropDownMenuModel._update [15]: Updating CustomQualityProfilesDropDownMenuModel.
2019-08-13 10:58:17,155 - DEBUG - [MainThread] UM.Qt.QtRenderer._initialize [181]: Support for Vertex Array Objects: True
2019-08-13 10:58:17,162 - DEBUG - [MainThread] UM.View.GL.OpenGL.__init__ [104]: Initialized OpenGL subsystems.
2019-08-13 10:58:17,167 - DEBUG - [MainThread] UM.View.GL.OpenGL.__init__ [105]: OpenGL Version:  4.1.0 - Build 26.20.100.6913
2019-08-13 10:58:17,174 - DEBUG - [MainThread] UM.View.GL.OpenGL.__init__ [106]: OpenGL Vendor:   Intel
2019-08-13 10:58:17,179 - DEBUG - [MainThread] UM.View.GL.OpenGL.__init__ [107]: OpenGL Renderer: Intel(R) HD Graphics 520
2019-08-13 10:58:17,184 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [56]: Loading shader file [C:\Program Files\Ultimaker Cura 4.2\resources\shaders\default.shader]...
2019-08-13 10:58:17,204 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [56]: Loading shader file [C:\Program Files\Ultimaker Cura 4.2\resources\shaders\selection.shader]...
2019-08-13 10:58:17,220 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [56]: Loading shader file [C:\Program Files\Ultimaker Cura 4.2\resources\shaders\default.shader]...
2019-08-13 10:58:17,243 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [56]: Loading shader file [C:\Program Files\Ultimaker Cura 4.2\resources\shaders\composite.shader]...
2019-08-13 10:58:17,282 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [56]: Loading shader file [C:\Program Files\Ultimaker Cura 4.2\resources\shaders\overhang.shader]...
2019-08-13 10:58:17,317 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [56]: Loading shader file [C:\Program Files\Ultimaker Cura 4.2\resources\shaders\striped.shader]...
2019-08-13 10:58:17,356 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [56]: Loading shader file [C:\Program Files\Ultimaker Cura 4.2\resources\shaders\transparent_object.shader]...
2019-08-13 10:58:17,387 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [56]: Loading shader file [C:\Program Files\Ultimaker Cura 4.2\resources\shaders\striped.shader]...
2019-08-13 10:58:17,429 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [56]: Loading shader file [C:\Program Files\Ultimaker Cura 4.2\resources\shaders\default.shader]...
2019-08-13 10:58:17,457 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [56]: Loading shader file [C:\Program Files\Ultimaker Cura 4.2\resources\shaders\grid.shader]...
2019-08-13 10:58:17,487 - DEBUG - [MainThread] UM.View.GL.ShaderProgram.load [56]: Loading shader file [C:\Program Files\Ultimaker Cura 4.2\resources\shaders\platform.shader]...
2019-08-13 10:58:17,684 - DEBUG - [MainThread] cura.Machines.QualityManager.initialize [136]: Lookup tables updated.
2019-08-13 10:58:17,815 - DEBUG - [MainThread] cura.Machines.Models.QualityProfilesDropDownMenuModel._update [61]: Updating QualityProfilesDropDownMenuModel.
2019-08-13 10:58:17,833 - DEBUG - [MainThread] cura.Machines.Models.CustomQualityProfilesDropDownMenuModel._update [15]: Updating CustomQualityProfilesDropDownMenuModel.
2019-08-13 10:58:19,997 - DEBUG - [MainThread] cura.TaskManagement.OnExitCallbackManager.triggerNextCallback [51]: No more on-app-exit callbacks to process. Tell the app to exit.
2019-08-13 10:58:20,002 - INFO - [MainThread] cura.CuraApplication.closeApplication [583]: Close application
2019-08-13 10:58:20,017 - DEBUG - [MainThread] UM.Qt.QtApplication.windowClosed [434]: Shutting down cura
2019-08-13 10:58:20,117 - DEBUG - [MainThread] CuraEngineBackend.CuraEngineBackend._terminate [292]: Attempting to kill the engine process
2019-08-13 10:58:20,118 - DEBUG - [MainThread] CuraEngineBackend.CuraEngineBackend._terminate [298]: Killing engine process
2019-08-13 10:58:20,122 - DEBUG - [MainThread] CuraEngineBackend.CuraEngineBackend._terminate [301]: Engine process is killed. Received return code 1
Routout commented 5 years ago

Earlier is after normally started and closed cura. After that I did a windows reboot and again Cura crashes, and theres nothing in the logs.

LipuFei commented 5 years ago

Hi @bvalat @Routout @SkiddieTech , I've created a Cura build with:

The download link is https://we.tl/t-SdbysJKPzg. Could you help us to test it? Thanks!

Please note that although this build has a file name Cura-4.1.99, it's actually created with the latest changes from the master branch, so this build is not so stable, it's only for testing purposes. Also backup your C:\Users\<your-user-name>\AppData\Roaming\cura\4.1 if you have one, because this build will use that folder.

bvalat commented 5 years ago

Your test Version is working for me. No more updatechecker plugin crash or file saving with anonymous data enabled and i can sign in my cloud account. So it fixes this ticket. But it still has the "won't start sometimes". I have to start 3 times. The two first launch just hang (0kb stderr stdout). I think this is another issue so i'll create another issue for it.

LipuFei commented 5 years ago

@bvalat Many thanks! I think the OpenSSL issues we found so far should be fixed. Note that this build is not really stable, so it's hard to say if it's still a problem with the HTTPS connections. We can check the log files see what's going on.

bvalat commented 5 years ago

The problem is that when it hangs, there is no log or starting screen. Just the cura process go up to ~60Mb and then fall basck to ~54-53mb and stays that way. But if i launch it several times it finishes to launch.

bvalat commented 5 years ago

I forgot to thank you for a such quick 3.5.7 build. Your test build and official 4.2.1 behave the same way for the hang on start. Since we had those problem before upgrading ssl and/or python, i'm not sure it's realy related so I opened another issue for the hang part.

LipuFei commented 5 years ago

@bvalat I will wrap this ticket up. Let's discuss the hanging issue in #6197.