[BUG] "Refused" when trying to enable Prusa Connect / when restarting the printer

murk-sy commented 1 month ago

Printer model

XL, Mini (likely all)

Firmware version

6.0.2 (and some previous versions)

Upgrades and modifications

No response

Printing from...

Prusa Connect

Describe the bug

After restarting the printer, Prusa Connect fails to reconnect for an extended period of time, until suddenly connecting perhaps a day or so later - seemingly randomly.

How to reproduce

It's a difficult issue so I'll give some background:

Network setup

mostly Ubiquiti equipment (everything that isn't a dumb switch)
has 5 DNS servers set up
primary DNS server is a local one that only has a handful of domains covered
others are 2 cloudflare and 2 google
all printers are connected via ethernet via the same switch
printer IPs are assigned by DHCP (they are preset/static)

Minis

There are 4 minis on the same network, one of which currently has the "refused" issue (happened on restart after upgrading to 6.0.2 from 6.0.1) - so far it has only happened on the XL. None of them have wifi cards installed. Since Connect has become "stable" some versions ago (couldn't tell you a concrete version or date), I had no weird connection related issues.

On one where Connect is working, I turned it off, waited 15 second, restarted it, and it did the following:

Acquire IP immediately
Connect throws TLS error a few times
Connect is online

Disabling Connect and re-enabling it causes it to be in "Connecting" for about 8 seconds, and then Online immediately after.

XL

Currently runs into this issue every time after restart, which wasn't very helpful due to a few crashes happening in recent version. Even if Connect was working perfectly fine

I honestly couldn't tell you at what version this has started but I'm fairly confident it hasn't always been the case.

Restarting the printer and capturing traffic based on the MAC address only shows DHCP and ARP requests. (67 being the printer, 123 being the router)

Expected behavior

No response

Files

I don't have anything concrete at this point, but I'm willing to do network captures/crash dumps/various tests on dev requests.

murk-sy commented 4 weeks ago

Add-on info:

XL (currently online on Connect and normally accessible)

Mini (currently offline on Connect, not accessible via Link or ping)

danopernis commented 4 weeks ago

Hi @murk-sy thanks for the report. Since you seem quite technologically capable, can you please try to obtain printer logs? Those are printed to serial line on baudrate 57600.

murk-sy commented 3 weeks ago

Didn't know there's different things on different baudrates - that's neat. Had to use vscode serial monitor for it, since pronterface didn't like it.

XL

I've actually managed to resolve it, at least for XL - within this log i've recreated a blank wifi config and loaded it. Even restarting the printer, it reconnects perfectly fine immediately.

When it was broken, the situation was as follows:

Eth was chosen as default interface
Wlan had credentials entered, but did not have an ip (at least not displayed, I don't recall seeing it in Unifi)
At some point before the XL was connected via Wlan (possibly on same ip, I don't recall), but ended up using Eth due to connectivity issues at the time.

So my gut feeling for the issue on the XL:

Eth was selected as default
Wlan had correct credentials and was (partially) connected
Connect attempted to use Wlan despite not being selected as default

Removed some fluff and anonymised SSID.

....
641.525s [INFO  - GUI:4] Distributing event clicked
641.526s [INFO  - GUI:4] Distributing event child click
641.627s [ERROR - Network:12] mdns_resp_remove_netif: Not an active netif
641.628s [INFO  - ESPIF:12] Link went down
641.755s [WARN  - ESPIF:12] Recovered from UART error
642.279s [INFO  - ESPIF:12] MAC: 0c:b8:15:22:a1:4c
642.280s [INFO  - ESPIF:12] Joining AP ###ACCESS-POINT-NAME###:*(11)
642.484s [INFO  - ESPIF:12] MAC: 0c:b8:15:22:a1:4c
643.282s [INFO  - ESPIF:12] Link went up
644.562s [INFO  - GUI:4] Distributing event button down
644.673s [INFO  - GUI:4] Distributing event button up
644.674s [INFO  - GUI:4] Distributing event clicked
644.675s [INFO  - GUI:4] Distributing event child click
644.743s [ERROR - Network:12] mdns_resp_remove_netif: Not an active netif
644.777s [ERROR - Network:12] mdns_resp_remove_netif: Not an active netif
644.778s [INFO  - ESPIF:12] Link went down
644.905s [WARN  - ESPIF:12] Recovered from UART error
645.429s [INFO  - ESPIF:12] MAC: 0c:b8:15:22:a1:4c
645.430s [INFO  - ESPIF:12] Joining AP ###ACCESS-POINT-NAME###:*(11)
645.562s [INFO  - ESPIF:12] MAC: 0c:b8:15:22:a1:4c
646.362s [INFO  - ESPIF:12] Link went up
656.128s [INFO  - connect:14] Creating of connection failed
661.961s [INFO  - GUI:4] Distributing event value/index changed
....
675.345s [INFO  - GUI:4] Distributing event clicked
675.346s [INFO  - Marlin:8] enqueueing "M1587 I"
675.349s [INFO  - USBHost:16] MSC readahead stat speculative reads=117, hit=93, missed=106, blocking=106
675.349s [INFO  - GUI:4] Distributing event focus set
675.381s [INFO  - GUI:4] Distributing event capture set
677.347s [INFO  - Marlin:8] busy: processing
677.536s [INFO  - GUI:4] Distributing event value/index changed
....
679.640s [INFO  - GUI:4] Distributing event clicked
679.718s [INFO  - Network:8] ESP credentials generated to /usb/prusa_printer_settings.ini
680.824s [INFO  - GUI:4] Distributing event button down
....
682.355s [INFO  - GUI:4] Distributing event clicked
682.356s [INFO  - Marlin:8] enqueueing "M1587"
682.358s [INFO  - USBHost:16] MSC readahead stat speculative reads=152, hit=124, missed=139, blocking=139
682.399s [INFO  - GUI:4] Distributing event focus set
682.399s [INFO  - GUI:4] Distributing event capture set
684.357s [INFO  - Marlin:8] busy: processing
684.967s [ERROR - Network:12] mdns_resp_remove_netif: Not an active netif
684.967s [INFO  - ESPIF:12] Link went down
685.068s [ERROR - Network:12] netif is not up, old style port?
685.478s [WARN  - ESPIF:12] Recovered from UART error
685.618s [INFO  - ESPIF:12] MAC: 0c:b8:15:22:a1:4c
685.619s [INFO  - ESPIF:12] Joining AP :*(0)
685.841s [INFO  - ESPIF:12] MAC: 0c:b8:15:22:a1:4c
686.357s [INFO  - Marlin:8] busy: processing
688.357s [INFO  - Marlin:8] busy: processing
690.357s [INFO  - Marlin:8] busy: processing
692.357s [INFO  - Marlin:8] busy: processing
694.357s [INFO  - Marlin:8] busy: processing
694.431s [INFO  - GUI:4] Distributing event value/index changed
....
694.853s [INFO  - GUI:4] Distributing event focus set
694.871s [ERROR - Network:12] mdns_resp_remove_netif: Not an active netif
694.972s [ERROR - Network:12] netif is not up, old style port?
695.441s [WARN  - ESPIF:12] Recovered from UART error
695.523s [INFO  - ESPIF:12] MAC: 0c:b8:15:22:a1:4c
695.524s [INFO  - ESPIF:12] Joining AP :*(0)
695.623s [INFO  - GUI:4] Distributing event value/index changed
695.624s [INFO  - GUI:4] Distributing event encoder minus
695.649s [INFO  - ESPIF:12] MAC: 0c:b8:15:22:a1:4c
695.692s [INFO  - GUI:4] Distributing event value/index changed
....
703.980s [INFO  - GUI:4] Distributing event clicked
716.283s [INFO  - USBHost:16] MSC readahead stat speculative reads=184, hit=152, missed=172, blocking=168
716.373s [INFO  - connect:14] No transfer to recover
---- Closed serial port COM5 due to disconnection from the machine ----
---- Opened the serial port COM5 ----
12.889s [INFO  - MarlinServer:8] ExtUI: onFactoryReset
12.890s [INFO  - Marlin:8]   G21    ; Units in mm (mm)
12.890s [INFO  - Marlin:8] 
12.890s [INFO  - Marlin:8] Filament setting12.954s [INFO  - Marlin:8] PID settings:
12.954s [INFO  - Marlin:8]   M301 P14.00 I1.00 D100.00
12.955s [INFO  - Marlin:8]   M301 P14.00 I1.00 D100.00
12.955s [INFO  -12.965s [INFO  - Marlin:8] Filament load/unload lengths:
12.965s [INFO  - Marlin:8]   M603 T0 L50.00 U105.00
12.966s [INFO  - Marlin:8]   M603 T1 L50.00 U105.00
12.966s [INFO  - Marli13.220s [INFO  - Marlin:8] Testing X connection... OK
13.221s [INFO  - Marlin:8] Testing Y connection... OK
13.221s [INFO  - Marlin:8] Testing Z connection... OK
13.226s [INFO  - Marlin:8] Testing E connection... OK
13.226s [INFO  - MarlinServer:8] ExtUI: onFactoryReset
13.284s [INFO  - MarlinServer:8] ExtUI: onFactoryReset
13.393s [INFO  - Marlin:8] Setup complete
13.395s [INFO  - Marlin:8] enqueueing "T5 S1 M0"
13.401s [INFO  - GUI:4] Distributing event focus set
13.402s [INFO  - GUI:4] Distributing event Marlin media changed
13.408s [ERROR - Network:12] mdns_resp_remove_netif: Not an active netif
13.414s [INFO  - USBHost:16] MSC readahead stat speculative reads=0, hit=0, missed=0, blocking=0
13.432s [ERROR - Network:12] mdns_resp_remove_netif: Not an active netif
13.438s [INFO  - connect:14] Creating of connection failed
13.473s [INFO  - Dwarf_2:10] [INFO  - ModbusControl:0] Dwarf select state: NO
13.483s [INFO  - Dwarf_3:10] [INFO  - ModbusControl:0] Dwarf select state: NO
13.493s [INFO  - Dwarf_4:10] [INFO  - ModbusControl:0] Dwarf select state: NO
13.504s [INFO  - Dwarf_5:10] [INFO  - ModbusControl:0] Dwarf select state: NO
13.517s [INFO  - Dwarf_2:10] 3.557s [INFO  - ModbusControl:0] Set hotend temperature: 0
13.526s [INFO  - Dwarf_3:10] 3.566s [INFO  - ModbusControl:0] Set hotend temperature: 0
13.5313.535s [INFO  - Dwarf_4:10] 3.573s [INFO  - ModbusControl:0] Set hotend temperature: 0
13.547s [INFO  - Dwarf_5:10] 3.579s [INFO  - ModbusControl:0] Set hotend temperature: 0
3s [ERROR - Network:12] netif is not up, old style port?
13.562s [WARN  - ESPIF:12] Recovered from UART error
13.563s [INFO  - Dwarf_2:10] 3.557s [INFO  - ModbusControl:0] Set Heatbrea13.565s [ERROR - Network:12] netif is not up, old style port?
13.573s [INFO  - Dwarf_3:10] 3.566s [INFO  - ModbusControl:0] Set Heatbreak requested temperature: 36
13.582s [INFO  - Dwarf_4:10] 3.573s [INFO  - ModbusControl:0] Set Heatbreak requested temperature: 36
13.592s [INFO  - Dwarf_5:10] 3.580s [INFO  - ModbusControl:0] Set Heatbreak requested temperature: 36
13.646s [INFO  - Dwarf_2:10] 3.557s [INFO  - ModbusControl:0] Set print fan PWM:: 0
13.652s [INFO  - Dwarf_3:10] 3.566s [INFO  - ModbusControl:0] Set print fan PWM:: 0
13.658s [INFO  - Dwarf_4:10] 3.573s [INFO  - ModbusControl:0] Set print fan PWM:: 0
13.664s [INFO  - Dwarf_5:10] 3.580s [INFO  - ModbusControl:0] Set print fan PWM:: 0
13.967s [INFO  - GUI:4] Distributing event child changed
14.084s [INFO  - ESPIF:12] MAC: 0c:b8:15:22:a1:4c
14.085s [INFO  - ESPIF:12] Joining AP :*(0)
14.209s [INFO  - ESPIF:12] MAC: 0c:b8:15:22:a1:4c
20.376s [INFO  - GUI:4] Distributing event value/index changed
20.377s [INFO  - GUI:4] Distributing event encoder plus
27.882s [INFO  - GUI:4] Distributing event capture set
27.883s [INFO  - GUI:4] Distributing event focus set
28.266s [INFO  - USBHost:16] MSC readahead stat speculative reads=117, hit=93, missed=106, blocking=106
28.353s [INFO  - connect:14] No transfer to recover
29.178s [INFO  - GUI:4] Distributing event value/index changed
29.179s [INFO  - GUI:4] Distributing event encoder plus
....
61.757s [INFO  - GUI:4] Distributing event focus lost
---- Closed the serial port COM5 ----

I will try recreating the issue. Though still doesn't explain why one of the Minis is having problems now. Might also be a broken config frankly but I'm running a print on it right now.

murk-sy commented 3 weeks ago

XL

Managed to reproduce, I believe reliably.

Connect printer via eth (using assigned DHCP?)
Create credentials file with valid wlan settings (using DHCP)
Change wlan to use static ip
Restart printer
Connect will error/refuse

To undo:

Change wlan to use DHCP (in menu it seems DHCP is already selected (with ip 0.0.0.0)? Change to static and back to DHCP)
Connect will go online normally

Mini

Still not 100% sure what the issue is on one of the minis, but I've had "set up wlan" popups before, so the printer might think it has a wlan card installed, causing the same issue? I'll check once the print is done, likely tomorrow.

murk-sy commented 3 weeks ago

Mini (may be a slightly different issue)

Edit: I managed to fix the issue on the mini and then re-break it... somehow. Working to make it reproducible.

Edit 2:

When it doesn't seem to acquire an IP, doing the following seems to resolve it:

Set wifi to static and back to dhcp
Set eth to static and back to dhcp
Turn off and unplug the network cable
Turn back on after 10 seconds
Replug network cable after fully loaded (important!)
Works again (might need a few seconds to connect)

Doing the following seems to re-break it:

Set wifi to static
Set eth to static and back to dhcp (eth at this point still works)
Turn off for 10 seconds
Broken again

I've tried reproducing the issue on other minis but no dice so far. Will try to load the same kind of config as I did on mini2, but a bit later. But I think it might be essentially the same issue as on the XL.

Original post below:

I've sent a zip archive with the following files:
- 1-prusa_printer_settings-from-prusaconnect.ini
- 2-mini2-log-before-loading-clearstatic.txt
- 3-mini2_dump.bin
- 4-prusa_printer_settings_clear_static.ini
- 5-mini2-log-after-loading-clearstatic.txt
- 6-mini2_dump_after-loading-clearstatic.bin
- 7-prusa_printer_settings_set_static_to_0.ini
- 8-mini2-log-after-loading-set-to-0.txt
- 9-mini2_dump_after-set-static-to-0.bin

I've noticed that the mini with the issue (referred to as mini2) has had a static IP in its config for a while. Likely because I've had issues with DHCP.
Loading just the default settings from Connect didn't do much for that setting, so I tried importing clearstatic ini, which had blank entries. That didn't work, so I set the IPs to 0, which finally cleared it (should be visible in dump 9 too).

However, the printer simply isn't pulling an IP via DHCP. It's trying, but it's not being assigned it seems.
(61 is mini2, 123 is router/dhcp server)
https://github.com/prusa3d/Prusa-Firmware-Buddy/assets/1211672/ae75dfc3-e0f6-4e4a-b3f1-31fe9a2f8b74

I haven't tried a factory reset yet, to make sure it's reproducible, since I'm fairly sure it's a weird config issue. The board itself is from february 2022 (replaced after, funnily enough, some weird network issues), and it's *probably* had a factory reset since then, but I can't say for sure.

prusa3d / Prusa-Firmware-Buddy