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

Move autoreporting out of the temperature ISR #3180

Merged
merged 3 commits into from
Jun 21, 2021

Conversation

wavexx
Copy link
Collaborator

@wavexx wavexx commented Jun 6, 2021

Code running in the temperature ISR needs to be fully reentrant, which
is hard to track down.

Move autoreporting to the main processing loop. This can make the
autoreporting slower or pause at times, but removes the reentrant
restriction, which allows us to use printf_P.

Code running in the temperature ISR needs to be fully reentrant, which
is hard to track down.

Move autoreporting to the main processing loop. This can make the
autoreporting slower or pause at times, but removes the reentrant
restriction, which allows us to use printf_P.
This makes autoreport work more consistently.
This avoids the "busy" output interleaving with regular output in very
rare scenarios.

We should focus in finding which calls are not using manage_inactivity()
properly instead of working it around.
@wavexx
Copy link
Collaborator Author

wavexx commented Jun 6, 2021

With the last commit, we also move the busy-protocol processing out of the temperature ISR. The call itself is safe but it can cause legitimate output to be broken if the ISR happens at the wrong time.

The temperature ISR should ideally only manage temperature.

wavexx added a commit to wavexx/Prusa-Firmware that referenced this pull request Jun 17, 2021
The longpress function is currently called within the temperature ISR,
which is bogus. Calling the longpress function at the wrong moment
can corrupt the menu buffers.

Move the call to the main loop by changing the logic slightly:

- still sample the lcd buttons inside the temperature ISR, which keeps
  scrollong/pressing responsive, but...
- set a flag to indicate that longpress has been triggered instead of
  calling the function directly
- call the function on the next manage_inactivity run

Combined with prusa3d#3180 this removes _most_ unsafe operations out of the ISR
which can happen during a normal run (max/mintemp warnings are still an
exception).
@DRracer DRracer added this to the FW 3.10.1 milestone Jun 21, 2021
@DRracer DRracer merged commit eafdf6c into prusa3d:MK3 Jun 21, 2021
@wavexx wavexx deleted the main_host_autoreport branch June 23, 2021 06:33
FormerLurker pushed a commit to FormerLurker/Prusa-Firmware that referenced this pull request Sep 6, 2021
* Redraw "Preheating to load" in full when modified by other actions

Check for lcd_draw_update to see if the lcd has been altered outside the
function and redraw the screen if full.

This fixes scenarios such as prusa3d#3129 where the "Card removed" message or
the SD menu is entered from outside the function's control.

This requires checking/resetting bFilamentWaitingFlag carefully to avoid
re-entering this function _twice_ (raise_z_above will run the main
loop until complete).

* Fix the eeprom address documentation

* Farm workaround M1 message

Farmers want to abuse a bug from the previous firmware releases
- they need to see the filename on the status screen instead of "Wait for user..."
So we won't update the message in farm mode...

* Allow D2 to be enabled selectively

* Fix D2 to read the entire SRAM content

Allow to read up to 0x21ff, which is the last byte of SRAM.  Set default
starting address to 0x200, which is the first true byte.

0x0-200 is mapped to register/io space and could cause issues when read
from bi-directional registers.

* Unify D2 and D3 handling

Handle reading/writing memory using the same base functions
in order to save space.

* Implement reading XFLASH with D6

This requires expanding the dcode_core address type to 32bit type,
thus enlarges the D2/D3 implementation as a result.

Still allow to save all the original space if D6 is disabled, for now.

* Remove PROGMEM handling from print_mem until D5 uses dcode_core

Handling PROGMEM also requires a 32bit address type.

* D[236]: remove "busy" messages while dumping, avoid WDT

* D6: also hide declaration behind conditional

* D6: add documentation

* Move "xflash" include inside the conditional

* Introduce "xflash_layout" to organize XFLASH's content

Update the language code to use the new LANG_OFFSET definition
and remove hard-coded flash sizes.

* xflash: remove some duplication

* xflash: add xflash_multipage_program and documentation

Add a new high-level command to perform multipage writes quickly.

* xfdump: implement dump-to-xflash functionality

Update xflash_layout to include information about the dump, which sits
at the end of xflash.

* lang/fw-build.sh: check for language data size during build

Ensure the language data always fits the reserved space in the XFLASH.

The script *should* use the LANG_SIZE definition from "xflash_layout",
which can be obtained by preprocessing the source code.

At the moment though this step has been omitted since running
arduino-builder to preprocess the source requires extra flags passed by
build.sh. The size has been hard-coded (and it's unlikely to change
given the content size is constant for the architecture).

* Dcodes: add D20/D21/D22 to generate/read/clear dumps

* Implement EMERGENCY_DUMP for offline analysis

If EMERGENCY_DUMP is defined, crash and dump using the new xflash dump
functionality instead of just continuing with an error message.

When an emergency crash is stored, the first restart after a crash
displays a message that debug data is available and to contact support
to submit the crash for analysis.

* Implement MENU_DUMP: offline memory dump from "Support"

If MENU_DUMP is enabled, a new entry at the end of the "Support" menu is
added that allows to dump memory for offline use.

This allows to trigger a memory dump at any moment during regular usage
(either idling or printing) and to recover the dump later even after a
hardware reset.

* Typo

* xfdump: fix build with XFLASH_DUMP disabled

* lang/fw-build.sh: fix padding calculation

* config: add sanity checks for XFLASH_DUMP options

* xfdump: reuse standard definitions for SRAM size/offset

* Dcodes: fix daddr_t type when only XFLASH_DUMP is enabled

* Document new applicable build options in the variant files

Document, but don't enable them.
Leave exiting functionality unchanged for now.

* xfdump: defensive static checks to ensure dump location always fits

* xfdump: fix size check

* dcode_code: fix inverted define to print larger types

* xfdump: fix another off-by-one static size check

* xfdump_layout: add some comments

* D6: remove option for unsupported models

* Fix millis reference

* WDR crash initial

* Fix XFLASH_DUMP print_mem

* Dump header as well

* xfdump_full_dump_and_reset: set a guaranteed minimum WDT

Just prior to dumping, reset the WDT to a known-safe (and not too long)
interval that guarantees a complete dump.

* Enable the "WDR reset" menu item in DEBUG_BUILD only

* Move "WDR dump" inside EMERGENGENCY_DUMP

* Rename dump_crash_source to dump_crash_reason

* xfdump: report to the host that a dump is available

As suggested by @3d-gussner, announce to the host that a dump is
available for retrieval using an action "dump_available".

Any kind of dump is announced (even if manually triggered).

To avoid reading from xflash twice, remove some duplication and return
the crash reason directly in xfdump_check_state().

* xfdump_erase: remove redundant XFLASH_SPI_ENTER()

* Introduce STACK_GUARD_MARGIN in all variants

Create a gap between the BSS and the stack guard.
Set this gap (STACK_GUARD_MARGIN) to 32 bytes in all variants.

The gap serves two purposes:

- Detect a stack overflow earlier (falsely triggering in overtight
  situations is OK!), so that we can hopefully avoid smashing
  the heap and have a clean view during the dump.

- Reserve spack space itself for the stack dumping machinery,
  which is going to grow the stack even further.

Remove get_stack_guard_test_value() which was unused.

* Fix usage of RAMEND

RAMEND is the last valid address, not one-past as I expected it to be...

* Implement an online crash dumper for MK2.5 boards

When XFLASH is not available, allow users to request _online_ crash
dumps by using D23 (since these require active user cooperation).

Once enabled, instead of just rebooting, dump memory directly to
the serial.

As similarly done with EMERGENCY_DUMP, we have two features that can be
enabled:

EMERGENCY_SERIAL_DUMP: enables dumping on crash after being requested
MENU_SERIAL_DUMP: allow triggering the same manually through the support
menu.

* Report crash also in MK2.5, fix stack_error abuse

Rename EEPROM_CRASH_ACKNOWLEDGED to EEPROM_FW_CRASH_FLAG.

Use EEPROM_FW_CRASH_FLAG to always set the last crash reason, which
simplifies handling between the online/offline variants.

Make stack_error safe, by setting the flag and restarting immediately,
so that the error can be shown after restart.

* Untangle a bit some recursive include mess

* xflash_dump is now always required in all variants

* Move stack checking to the temperature ISR

Now that the stack_error function is truly minimal,
we can check for stack errors much more frequently.

Also move away stack_error from ultralcd to Marlin_main.

* Move inclusion closer to the usage point

* serial_dump_and_reset: do not completely disable WDT

Set it to 8s which is long enough to complete the dump.

* serial_dump_and_reset: turn on print fan while dumping

To avoid scorching the sheet while dumping close to the bed.

* Enable debugging features on all variants

- XFlash crash dumper on MK3+ series
- Online crash dumper on MK2.5+ series
- D2/D6 on MK3+ series
- D2 on MK2.5+ series

* bad ISR catch

* serial_dump: add description about bad_isr

* Remove duplication in crash handlers

It's kind of nice that all handlers eventually came to become the same.

* emergency handlers: always save SP _at_ the crash location

Save SP which is closest to the crash location, which simplifies
debugging. For serial_dump, write SP just before the dump.
For xfdump, save SP in the dump header.

This makes xfdump_dump and xfdump_full_dump_and_reset() equivalent for
stack debugging.

* serial_dump: manipulate WDT just once

* serial_dump_and_reset: do not call manage_heater with interrupts disabled

Do not call manage_heater() in print_mem() if interrupts are already
disabled. This means we're running inside the crash handler.

* Add test code for the stack overflow handler

* Fix last commit

* xfdump: simplify stack debugging (sample pc+sp)

Instead of having to guess the PC where the SP was sampled, always take
both. This allows "seamless" stack decoding for both serial and xflash
dumps, since we don't have to guess which function generated the dump.

Make the core functions (doing the sampling) be ``noinline`` as well,
so that they always have valid frame.

* Handle Long-Press in the main loop

The longpress function is currently called within the temperature ISR,
which is bogus. Calling the longpress function at the wrong moment
can corrupt the menu buffers.

Move the call to the main loop by changing the logic slightly:

- still sample the lcd buttons inside the temperature ISR, which keeps
  scrollong/pressing responsive, but...
- set a flag to indicate that longpress has been triggered instead of
  calling the function directly
- call the function on the next manage_inactivity run

Combined with prusa3d#3180 this removes _most_ unsafe operations out of the ISR
which can happen during a normal run (max/mintemp warnings are still an
exception).

* Add some warnings in lcd_buttons_update

* GETPC: Do not manipulate the 32bit return address

We can do that offline, saving over 30 bytes of instructions.

* serial_dump: include hex prefix

* Remove ignored/incorrect PROGMEM

This PROGMEM is currently ignored by gcc, but even if it wasn't it
wouldn't be correct since the following code is expecting to read "item"
without fetching the array itself from PROGMEM.

* Move autoreporting out of the temperature ISR

Code running in the temperature ISR needs to be fully reentrant, which
is hard to track down.

Move autoreporting to the main processing loop. This can make the
autoreporting slower or pause at times, but removes the reentrant
restriction, which allows us to use printf_P.

* Move host_autoreport() to manage_inactivity()

This makes autoreport work more consistently.

* Also move host_keepalive to manage_inactivity()

This avoids the "busy" output interleaving with regular output in very
rare scenarios.

We should focus in finding which calls are not using manage_inactivity()
properly instead of working it around.

* Remove unnecessary assignment

* Fix unused static declaration warnings

Guard declarations using the appropriate defines

* Fix misleading indentation warnings by expanding tabs

* Clarify statement by adding extra braces

* Silence explicit case-fallthru

* Fix two new explicit case fallthru warnings

* Fixed C++ bug

* Use LCD_WIDTH instead of hardcoding 20

* optiboot_xflash comment about w25x20cl messages


Mention supported ICs

* Second attempt at retrieving the SN from the 32u2 IC

* Minor fixes to SD presence handling (prusa3d#3139)

* Remove forgotten function protorypes

* Fix code indentation

* Fix double sorting if SD card is inserted during setup()

* Correctly handle SD removal during sorting

* Fix spanish translation for MSG_UNLOAD_SUCCESSFUL (prusa3d#3185)

Fix spanish transtalation for MSG_UNLOAD_SUCCESSFUL by: jfestrada <jfestrada@cloudhd.eu>

* Remove "bonus" exclamation points from the crash message

* Fixup the DUMP_MAGIC constant

* Use uint8_t consistently for the block buffer's index

Instead of using a mixture of int8_t, unsigned char and (incorrectly)
int, use uint8_t consistently for indexing the current block.

This improves the performance of the wait loop in plan_buffer_line,
which currently expands all comparisons to a word for no reason.

This also extends the theoretical limit to 128 entries.
Add some static assertions to ensure BLOCK_BUFFER_SIZE is correct.

* Remove FW version parsing

as it can be done at compile time. Code size dropped by >800 bytes.

* xfdump: correctly erase all sectors in xfdump_erase

* Remove useless function EEPROM_read_st

* Work-around GCC LTO codegen bug in process_commands()

When building with GCC 4.9.2 (bundled with PF-build-env-1.0.6.*), -Os
and LTO enabled, PID_autotune gets automatically inlined into
process_commands().

Sadly, due to the massive size of process_commands(), it results in
codegen bug doing a partial stack overwrite in process_commands()
itself, manifesting as random behavior depending on the timing of
interrupts and the codepath taken inside the merged function.

Mark the function as noinline and add a note about the affected compiler
version in order to be checked again in the future.

* write_command() no line number handling

* Include "Dcodes.h" after "Marlin.h" for configuration

This is needed in order to get the function prototypes right according
to the actual enabled configuration.

* Improve/fix D23 for M2.5/S printers

- Move D23 into it's own function inside Dcodes
- Correctly include a break in the switch statement
- Show the dumper status (enabled/disabled) after toggling
- Allow to generate an immediate dump via g-code using D23 E for
  symmetry with D20 E

* Correctly read FW_VERSION_NR array from progmem

In PR prusa3d#3093 the progmem array FW_VERSION_NR was introduced to store the
version components, however the code didn't read it properly using the
pgm_read_* functions, making version comparisons fail.

Fix the existing/unused is_provided_version_newer() and reuse it in
show_upgrade_dialog_if_version_newer().

Similarly also read/update correctly the version in the eeprom.

* change boolean to bool

* Change nrFiles from int16_t to uint16_t

* Correct the C implementation for MultiU16X8toH16

The comment behind the ASM MultiU16X8toH16 was misleading.
It actually computes ((a<<8)*b)>>16, or (a*b)>>8.

Correct the comment and C reference implementation accordingly.

* Use fabs() instead of abs() when using floats

This saves 514 bytes of flash memory

* Print an error on unknown D-codes

This follows the same convention of M/G codes, so that the user knowns
that the D-code has been either handled or ignored.

* Remove spourious trailing whitespace in errors

* Consolidate "Unknown X-Code" to save 16 bytes

* Remove unused Sound_Save() function declaration

* Remove unused function lcd_choose_color()

* Improve mc_arc() parameters

- Make the mc_arc() function declaration consistent with the definition
- isclockwise is supposed to be bool type, given how it is used.

* * Remove redundant externs already included with temperature.h
* Add ifdefs in Dcodes.cpp when using extern variables

* Remove useless extern in cmdqueue.cpp

* lcd_change_fil_state has two extern's in Marlin.h, only one needed.

* Remove redundant extern variable is_usb_printing from tmc2130.cpp

This extern variable is included from Marlin.h

* Remove redundant extern variable lcd_encoder from menu.cpp

This extern variable is included from lcd.h

Co-authored-by: Yuri D'Elia <wavexx@thregr.org>
Co-authored-by: Panayiotis-git <32783577+Panayiotis-git@users.noreply.github.com>
Co-authored-by: D.R.racer <drracer@drracer.eu>
Co-authored-by: DRracer <drracer@seznam.cz>
Co-authored-by: Voinea Dragos <voinea.dragos.alexandru@gmail.com>
Co-authored-by: Yuri D'Elia <wavexx@users.noreply.github.com>
Co-authored-by: Jonas Meyer <Craftplorer@users.noreply.github.com>
Co-authored-by: metacollin <metacollin@electropi.mp>
Co-authored-by: jfestrada <jfestrada@users.noreply.github.com>
Co-authored-by: Guðni Már Gilbert <gudni.m.g@gmail.com>
@knobik
Copy link

knobik commented Feb 16, 2022

This code is responsible for my printer timing out in octoprint while using MMU2S, its not sending the keep-alive messages anymore like busy: processing and octoprint times out.

Send: N16 M190 S85*98
Recv: T:104.8 /240.0 B:49.1 /85.0 T0:104.8 /240.0 @:127 B@:127 P:0.0 A:34.3
Recv: echo:busy: paused for user
Printer seems to support the busy protocol, will adjust timeouts and set busy interval accordingly
Recv: T:104.5 /240.0 B:49.0 /85.0 T0:104.5 /240.0 @:127 B@:127 P:0.0 A:34.5
Recv: mmu_get_response - begin move: T-code
Recv: MMU <= 'T0'
Recv: echo:busy: processing
Recv: Unloading finished 2
Recv: T:105.0 /240.0 B:48.9 /85.0 T0:105.0 /240.0 @:127 B@:127 P:0.0 A:34.3
Recv: echo:busy: processing
Recv: mmu_get_response - begin move: load
Recv: T:106.9 /240.0 B:48.9 /85.0 T0:106.9 /240.0 @:127 B@:127 P:0.0 A:34.5
Recv: echo:busy: processing
Recv: T:109.7 /240.0 B:49.1 /85.0 T0:109.7 /240.0 @:127 B@:127 P:0.0 A:34.5
Recv: echo:busy: processing
Recv: T:113.9 /240.0 B:49.3 /85.0 T0:113.9 /240.0 @:127 B@:127 P:0.0 A:34.7
Recv: echo:busy: processing
Recv: T:118.6 /240.0 B:49.9 /85.0 T0:118.6 /240.0 @:127 B@:127 P:0.0 A:34.7
Recv: echo:busy: processing
Recv: T:123.8 /240.0 B:50.2 /85.0 T0:123.8 /240.0 @:127 B@:127 P:0.0 A:34.9
Recv: echo:busy: processing
Recv: T:128.9 /240.0 B:50.8 /85.0 T0:128.9 /240.0 @:127 B@:127 P:0.0 A:35.0
Recv: echo:busy: processing
Recv: T:133.4 /240.0 B:51.4 /85.0 T0:133.4 /240.0 @:127 B@:127 P:0.0 A:35.1
Recv: echo:busy: processing
Recv: T:138.7 /240.0 B:52.2 /85.0 T0:138.7 /240.0 @:127 B@:127 P:0.0 A:35.4
Recv: echo:busy: processing
Recv: T:144.1 /240.0 B:53.0 /85.0 T0:144.1 /240.0 @:127 B@:127 P:0.0 A:35.5
Recv: echo:busy: processing
Recv: T:149.3 /240.0 B:53.6 /85.0 T0:149.3 /240.0 @:127 B@:127 P:0.0 A:35.4
Recv: echo:busy: processing
Recv: T:154.6 /240.0 B:54.4 /85.0 T0:154.6 /240.0 @:127 B@:127 P:0.0 A:35.4
Recv: echo:busy: processing
Recv: T:159.6 /240.0 B:55.3 /85.0 T0:159.6 /240.0 @:127 B@:127 P:0.0 A:35.7
Recv: echo:busy: processing
Recv: T:164.0 /240.0 B:55.7 /85.0 T0:164.0 /240.0 @:127 B@:127 P:0.0 A:36.0
Recv: echo:busy: processing
Recv: T:169.1 /240.0 B:56.3 /85.0 T0:169.1 /240.0 @:127 B@:127 P:0.0 A:35.8
Recv: echo:busy: processing
Recv: T:174.3 /240.0 B:56.8 /85.0 T0:174.3 /240.0 @:127 B@:127 P:0.0 A:35.8
Recv: echo:busy: processing
Recv: T:178.9 /240.0 B:57.3 /85.0 T0:178.9 /240.0 @:127 B@:127 P:0.0 A:35.8
Recv: echo:busy: processing
Recv: T:184.1 /240.0 B:57.9 /85.0 T0:184.1 /240.0 @:127 B@:127 P:0.0 A:35.9
Recv: echo:busy: processing
Recv: T:188.9 /240.0 B:58.4 /85.0 T0:188.9 /240.0 @:127 B@:127 P:0.0 A:36.1
Recv: echo:busy: processing
Recv: T:193.3 /240.0 B:58.9 /85.0 T0:193.3 /240.0 @:127 B@:127 P:0.0 A:36.2
Recv: MMU <= 'A'
Recv: MMU => 'ok'
Recv: mmu_get_response() returning: 1
Recv: ok
Send: N17 M113 S2*87
Recv: LCD status changed
Recv: T:197.53 E:0 B:59.4
Recv: T:198.1 /240.0 B:59.4 /85.0 T0:198.1 /240.0 @:127 B@:127 P:0.0 A:36.5
Recv: T:199.05 E:0 B:59.6
Recv: T:201.74 E:0 B:59.9
Recv: T:202.4 /240.0 B:60.0 /85.0 T0:202.4 /240.0 @:127 B@:127 P:0.0 A:36.3
Recv: T:204.73 E:0 B:60.3
Recv: T:206.96 E:0 B:60.5
Recv: T:207.4 /240.0 B:60.6 /85.0 T0:207.4 /240.0 @:127 B@:127 P:0.0 A:36.6
Recv: T:209.02 E:0 B:60.8
Recv: T:211.88 E:0 B:61.0
Recv: T:212.2 /240.0 B:61.1 /85.0 T0:212.2 /240.0 @:117 B@:127 P:0.0 A:36.7
Recv: T:213.33 E:0 B:61.2
Recv: T:215.73 E:0 B:61.4
Recv: T:216.6 /240.0 B:61.6 /85.0 T0:216.6 /240.0 @:102 B@:127 P:0.0 A:37.0
Recv: T:218.44 E:0 B:61.8
Recv: T:220.50 E:0 B:62.0
Recv: T:221.1 /240.0 B:62.2 /85.0 T0:221.1 /240.0 @:89 B@:127 P:0.0 A:36.7
Recv: T:223.06 E:0 B:62.3
Recv: T:224.44 E:0 B:62.5
Recv: T:225.1 /240.0 B:62.7 /85.0 T0:225.1 /240.0 @:78 B@:127 P:0.0 A:36.7
Recv: T:226.44 E:0 B:62.8
Recv: T:228.25 E:0 B:63.1
Recv: T:228.6 /240.0 B:63.1 /85.0 T0:228.6 /240.0 @:65 B@:127 P:0.0 A:37.0
Recv: T:230.31 E:0 B:63.4
Recv: T:231.80 E:0 B:63.6
Recv: T:232.4 /240.0 B:63.6 /85.0 T0:232.4 /240.0 @:49 B@:127 P:0.0 A:36.9
Recv: T:233.28 E:0 B:64.0
Recv: T:234.22 E:0 B:64.1
Recv: T:235.1 /240.0 B:64.2 /85.0 T0:235.1 /240.0 @:44 B@:127 P:0.0 A:36.8
Recv: T:235.39 E:0 B:64.5
Recv: T:236.48 E:0 B:64.6
Recv: T:237.2 /240.0 B:64.7 /85.0 T0:237.2 /240.0 @:38 B@:127 P:0.0 A:37.0
Recv: T:237.58 E:0 B:65.0
Recv: T:238.28 E:0 B:65.2
Recv: T:238.6 /240.0 B:65.3 /85.0 T0:238.6 /240.0 @:41 B@:127 P:0.0 A:37.2
Recv: T:238.67 E:0 B:65.4
Recv: T:239.53 E:0 B:65.7
Recv: T:240.0 /240.0 B:65.8 /85.0 T0:240.0 /240.0 @:38 B@:127 P:0.0 A:37.1
Recv: T:240.52 E:0 B:65.9
Recv: T:240.63 E:0 B:66.2
Recv: T:240.6 /240.0 B:66.3 /85.0 T0:240.6 /240.0 @:42 B@:127 P:0.0 A:37.3
Recv: T:240.94 E:0 B:66.5
Recv: T:241.46 E:0 B:66.7
Recv: T:241.3 /240.0 B:66.8 /85.0 T0:241.3 /240.0 @:44 B@:127 P:0.0 A:37.3
Recv: T:241.25 E:0 B:66.9
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N18 M105*30
Recv: T:242.08 E:0 B:67.1
Recv: T:241.8 /240.0 B:67.2 /85.0 T0:241.8 /240.0 @:44 B@:127 P:0.0 A:37.5
Recv: T:241.67 E:0 B:67.4
Recv: T:242.81 E:0 B:67.6
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N19 M105*31
Recv: T:242.5 /240.0 B:67.6 /85.0 T0:242.5 /240.0 @:40 B@:127 P:0.0 A:37.4
Recv: T:243.44 E:0 B:67.9
Recv: T:242.71 E:0 B:68.1
Recv: T:243.3 /240.0 B:68.2 /85.0 T0:243.3 /240.0 @:34 B@:127 P:0.0 A:37.5
Recv: T:243.96 E:0 B:68.3
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N20 M105*21
Recv: T:243.75 E:0 B:68.5
Recv: T:243.5 /240.0 B:68.7 /85.0 T0:243.5 /240.0 @:34 B@:127 P:0.0 A:37.6
Recv: T:244.17 E:0 B:68.8
Recv: T:243.96 E:0 B:69.0
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N21 M105*20
Recv: T:244.2 /240.0 B:69.1 /85.0 T0:244.2 /240.0 @:28 B@:127 P:0.0 A:37.3
Recv: T:244.06 E:0 B:69.2
Recv: T:243.96 E:0 B:69.5
Recv: T:244.3 /240.0 B:69.5 /85.0 T0:244.3 /240.0 @:28 B@:127 P:0.0 A:37.5
Recv: T:243.96 E:0 B:69.7
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N22 M105*23
Recv: T:244.58 E:0 B:70.0
Recv: T:244.4 /240.0 B:70.0 /85.0 T0:244.4 /240.0 @:26 B@:127 P:0.0 A:37.7
Recv: T:244.38 E:0 B:70.1
Recv: T:244.27 E:0 B:70.4
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N23 M105*22
Recv: T:244.7 /240.0 B:70.5 /85.0 T0:244.7 /240.0 @:21 B@:127 P:0.0 A:37.5
Recv: T:243.85 E:0 B:70.7
Recv: T:244.69 E:0 B:70.8
Recv: T:244.6 /240.0 B:71.0 /85.0 T0:244.6 /240.0 @:21 B@:127 P:0.0 A:38.1
Recv: T:244.69 E:0 B:71.2
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N24 M105*17
Recv: T:244.38 E:0 B:71.3
Recv: T:244.5 /240.0 B:71.4 /85.0 T0:244.5 /240.0 @:21 B@:127 P:0.0 A:37.8
Recv: T:244.27 E:0 B:71.6
Recv: T:244.27 E:0 B:71.8
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N25 M105*16
Recv: T:244.3 /240.0 B:71.9 /85.0 T0:244.3 /240.0 @:21 B@:127 P:0.0 A:37.7
Recv: T:244.38 E:0 B:72.0
Recv: T:244.48 E:0 B:72.3
Recv: T:243.9 /240.0 B:72.3 /85.0 T0:243.9 /240.0 @:24 B@:127 P:0.0 A:37.8
Recv: T:244.06 E:0 B:72.4
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N26 M105*19
Recv: T:243.85 E:0 B:72.7
Recv: T:243.5 /240.0 B:72.8 /85.0 T0:243.5 /240.0 @:25 B@:127 P:0.0 A:38.0
Recv: T:243.23 E:0 B:72.9
Recv: T:243.96 E:0 B:73.1
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N27 M105*18
Recv: T:243.5 /240.0 B:73.2 /85.0 T0:243.5 /240.0 @:22 B@:127 P:0.0 A:38.1
Recv: T:243.23 E:0 B:73.3
Recv: T:243.02 E:0 B:73.5
Recv: T:242.7 /240.0 B:73.6 /85.0 T0:242.7 /240.0 @:30 B@:127 P:0.0 A:38.1
Recv: T:242.50 E:0 B:73.8
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N28 M105*29
Recv: T:242.71 E:0 B:74.0
Recv: T:242.1 /240.0 B:74.0 /85.0 T0:242.1 /240.0 @:34 B@:127 P:0.0 A:38.1
Recv: T:241.98 E:0 B:74.1
Recv: T:241.77 E:0 B:74.4
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N29 M105*28
Recv: T:241.1 /240.0 B:74.5 /85.0 T0:241.1 /240.0 @:42 B@:127 P:0.0 A:38.2
Recv: T:241.98 E:0 B:74.6
Recv: T:241.56 E:0 B:74.8
Recv: T:241.6 /240.0 B:74.8 /85.0 T0:241.6 /240.0 @:34 B@:127 P:0.0 A:38.1
Recv: T:241.67 E:0 B:75.0
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N30 M105*20
Recv: T:241.35 E:0 B:75.2
Recv: T:242.3 /240.0 B:75.3 /85.0 T0:242.3 /240.0 @:21 B@:127 P:0.0 A:38.4
Recv: T:242.19 E:0 B:75.4
Recv: T:241.46 E:0 B:75.6
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N31 M105*21
Recv: T:242.0 /240.0 B:75.8 /85.0 T0:242.0 /240.0 @:23 B@:127 P:0.0 A:38.2
Recv: T:241.46 E:0 B:75.9
Recv: T:241.88 E:0 B:76.1
Recv: T:241.6 /240.0 B:76.1 /85.0 T0:241.6 /240.0 @:27 B@:127 P:0.0 A:38.3
Recv: T:241.98 E:0 B:76.4
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N32 M105*22
Recv: T:241.25 E:0 B:76.5
Recv: T:241.5 /240.0 B:76.5 /85.0 T0:241.5 /240.0 @:26 B@:127 P:0.0 A:38.5
Recv: T:241.56 E:0 B:76.7
Recv: T:241.35 E:0 B:76.9
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N33 M105*23
Recv: T:241.7 /240.0 B:76.9 /85.0 T0:241.7 /240.0 @:22 B@:127 P:0.0 A:38.5
Recv: T:241.56 E:0 B:77.1
Recv: T:241.25 E:0 B:77.3
Recv: T:241.8 /240.0 B:77.4 /85.0 T0:241.8 /240.0 @:19 B@:127 P:0.0 A:38.5
Recv: T:241.67 E:0 B:77.5
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N34 M105*16
Recv: T:240.52 E:0 B:77.7
Recv: T:240.9 /240.0 B:77.8 /85.0 T0:240.9 /240.0 @:29 B@:127 P:0.0 A:38.4
Recv: T:240.52 E:0 B:77.9
Recv: T:241.15 E:0 B:78.0
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N35 M105*17
Recv: T:241.0 /240.0 B:78.2 /85.0 T0:241.0 /240.0 @:26 B@:127 P:0.0 A:38.6
Recv: T:240.52 E:0 B:78.3
Recv: T:241.15 E:0 B:78.4
Recv: T:240.7 /240.0 B:78.5 /85.0 T0:240.7 /240.0 @:28 B@:127 P:0.0 A:38.4
Recv: T:241.04 E:0 B:78.7
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N36 M105*18
Recv: T:241.25 E:0 B:78.9
Recv: T:240.5 /240.0 B:79.0 /85.0 T0:240.5 /240.0 @:30 B@:127 P:0.0 A:38.6
Recv: T:240.94 E:0 B:79.0
Recv: T:240.73 E:0 B:79.3
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N37 M105*19
Recv: T:240.9 /240.0 B:79.3 /85.0 T0:240.9 /240.0 @:23 B@:127 P:0.0 A:38.7
Recv: T:240.73 E:0 B:79.4
Recv: T:240.73 E:0 B:79.6
Recv: T:240.6 /240.0 B:79.7 /85.0 T0:240.6 /240.0 @:26 B@:127 P:0.0 A:38.6
Recv: T:240.21 E:0 B:79.8
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N38 M105*28
Recv: T:240.42 E:0 B:80.0
Recv: T:240.4 /240.0 B:80.0 /85.0 T0:240.4 /240.0 @:28 B@:127 P:0.0 A:38.6
Recv: T:240.10 E:0 B:80.2
Recv: T:240.52 E:0 B:80.4
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N39 M105*29
Recv: T:240.5 /240.0 B:80.4 /85.0 T0:240.5 /240.0 @:25 B@:127 P:0.0 A:38.7
Recv: T:240.42 E:0 B:80.6
Recv: T:240.31 E:0 B:80.7
Recv: T:239.9 /240.0 B:80.8 /85.0 T0:239.9 /240.0 @:32 B@:127 P:0.0 A:38.6
Recv: T:240.00 E:0 B:80.9
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N40 M105*19
Recv: T:239.84 E:0 B:81.1
Recv: T:240.5 /240.0 B:81.2 /85.0 T0:240.5 /240.0 @:23 B@:127 P:0.0 A:38.7
Recv: T:240.21 E:0 B:81.3
Recv: T:239.84 E:0 B:81.5
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N41 M105*18
Recv: T:239.6 /240.0 B:81.6 /85.0 T0:239.6 /240.0 @:35 B@:111 P:0.0 A:38.8
Recv: T:240.00 E:0 B:81.7
Recv: T:239.61 E:0 B:81.8
Recv: T:239.6 /240.0 B:81.9 /85.0 T0:239.6 /240.0 @:33 B@:102 P:0.0 A:38.6
Recv: T:239.22 E:0 B:82.1
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N42 M105*17
Recv: T:239.30 E:0 B:82.3
Recv: T:239.6 /240.0 B:82.3 /85.0 T0:239.6 /240.0 @:32 B@:81 P:0.0 A:38.7
Recv: T:239.45 E:0 B:82.5
Recv: T:240.31 E:0 B:82.6
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N43 M105*16
Recv: T:239.6 /240.0 B:82.6 /85.0 T0:239.6 /240.0 @:32 B@:76 P:0.0 A:38.7
Recv: T:239.77 E:0 B:82.7
Recv: T:240.31 E:0 B:82.9
Recv: T:239.8 /240.0 B:82.9 /85.0 T0:239.8 /240.0 @:29 B@:76 P:0.0 A:38.7
Recv: T:240.31 E:0 B:83.0
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N44 M105*23
Recv: T:240.31 E:0 B:83.2
Recv: T:240.3 /240.0 B:83.2 /85.0 T0:240.3 /240.0 @:24 B@:60 P:0.0 A:38.8
Recv: T:239.77 E:0 B:83.2
Recv: T:240.63 E:0 B:83.4
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N45 M105*22
Recv: T:240.4 /240.0 B:83.4 /85.0 T0:240.4 /240.0 @:23 B@:73 P:0.0 A:38.8
Recv: T:240.94 E:0 B:83.5
Recv: T:240.52 E:0 B:83.6
Recv: T:240.4 /240.0 B:83.6 /85.0 T0:240.4 /240.0 @:23 B@:63 P:0.0 A:38.7
Recv: T:240.63 E:0 B:83.7
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N46 M105*21
Recv: T:240.00 E:0 B:83.7
Recv: T:240.4 /240.0 B:83.8 /85.0 T0:240.4 /240.0 @:24 B@:63 P:0.0 A:38.9
Recv: T:240.31 E:0 B:83.8
Recv: T:240.10 E:0 B:83.9
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N47 M105*20
Recv: T:240.2 /240.0 B:84.0 /85.0 T0:240.2 /240.0 @:26 B@:72 P:0.0 A:38.7
Recv: T:240.31 E:0 B:83.9
Recv: T:239.69 E:0 B:84.1
Recv: T:239.8 /240.0 B:84.0 /85.0 T0:239.8 /240.0 @:31 B@:83 P:0.0 A:38.8
Recv: T:239.30 E:0 B:84.1
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
Send: N48 M105*27
Recv: T:239.61 E:0 B:84.1
Recv: T:239.5 /240.0 B:84.1 /85.0 T0:239.5 /240.0 @:35 B@:88 P:0.0 A:38.8
Recv: T:238.75 E:0 B:84.2
Recv: T:238.59 E:0 B:84.2
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.

and after that point octoprint sends M112 as it times out.

@leptun
Copy link
Collaborator

leptun commented Feb 16, 2022

@knobik Thank you for reporting. Can you please upload an identical scenario as in the log above, but from serial.log of octoprint so that it has timestamps? Please also upload the gcode if possible. I assume version 3.10.1, MK3S with MMU2S (fw 1.0.6). Is this correct?

@knobik
Copy link

knobik commented Feb 16, 2022

@leptun
Copy link
Collaborator

leptun commented Feb 16, 2022

2022-02-16 12:53:49,850 - Send: Tx -------Octoprint did not wait for an OK response before sending line N16. Also, why did it not send it with a checksum and line number?? something is seriously wrong with this command and how it was sent
2022-02-16 12:53:49,852 - Send: N16 M190 S85*98

...

2022-02-16 12:54:31,277 - Recv: ok -------this was the ok for Tx, not line N16 as octoprint seems to think
2022-02-16 12:54:31,280 - Recv: LCD status changed
2022-02-16 12:54:31,282 - Send: N17 M113 S2*87 -------should not have sent this yet because only now did line N16 start being processed, not finished as octoprint thinks at this point

Because the printer is actually executing N16 instead of N17 (what octoprint thinks is happening), octoprint times out the N17 line because it gets no busy messages back, but rather heatup messages as is normal for M190.

What plugins are you using? What are your octoprint serial settings (timeouts/behaviours/etc...)

@knobik
Copy link

knobik commented Feb 16, 2022

@leptun plugins: nothing special, just basic stuff:
image

for timeouts, standard octoprint setup:
Screenshot from 2022-02-16 13-19-45

Screenshot from 2022-02-16 13-20-29

same for behaviors, octoprint defaults:
Screenshot from 2022-02-16 13-21-12

Screenshot from 2022-02-16 13-21-28

Problem started when i installed MMU2S and upgraded my i3 to 3.10.1

@leptun
Copy link
Collaborator

leptun commented Feb 16, 2022

Are you sure this is related to fw 3.10.1? To me it looks like a bug in octoprint. Can you try downgrading the firmware to see if anything improves. I for one doubt anything will change

@knobik
Copy link

knobik commented Feb 16, 2022

@knobik
Copy link

knobik commented Feb 16, 2022

@leptun shouldnt there be a busy: processing send while the hotend and bed are heating even when in Tx mode? (or shortly after)

@foosel
Copy link

foosel commented Feb 17, 2022

For the record, yes, busy: processing should be send on any lengthy operations that block printer communication. That includes long moves, heatups, whatever. So this is a bug in the firmware, plain and simple.

And OctoPrint sending Tx without line number and checksum has always been the case, since that is not a valid GCODE (it neither starts with G or M and it's also not a T or F followed by an integer) and to not cause issues with some firmwares out there those are send without line numbers and checksums and without using up an ok. That's always been the case, that's not a change in behaviour, and that's also something that can be configured in OctoPrint.

@leptun leptun mentioned this pull request Feb 19, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants