Repetier Server "hängt" nach Druck-Start

pschlan · November 2023

Hallo,

wenn ich einen Gcode-Druck starte, "hängt" sich Repetier-Server auf, d.h. der Druck beginnt nicht und ich kann ihn auch nicht mehr abbrechen. Das Web-Interface zeigt dann nur noch leere Seiten (das Menü oben ist jedoch noch da). Im Menü wird der Drucker als pausiert angezeigt, ein Klick auf den Play-Button bewirkt aber nichts. Ich habe schon eine neue SD-Karte, einen anderen Raspberry Pi (beide 3B+) und eine Neuinstallation vom Image (1.4.13) probiert.

Mit einer sehr alten OEM-Version (< 1.0) klappte alles einwandfrei. Ich habe die gleiche Drucker-Config importiert.

Folgende Logs finde ich nach versuchtem Druck. Das geht nur, wenn ich das Log laufen lasse während ich den Druckversuch starte, da ich es danach nicht mehr aufrufen kann (weiße Seite, s.o.)

Send:13:32:09.117: N4 M220 S100 ; Speed multiplier 100%

Recv:13:32:09.131: ok

Send:13:32:09.131: N5 M221 S100 ; Flow multiplier 100%

Recv:13:32:09.147: ok

Send:13:32:09.147: N6 G92 E0

Recv:13:32:09.163: ok

Send:13:32:09.163: N7 G90

Recv:13:32:09.180: ok

Recv:13:32:09.180: FilamentAvailable_T0 = true

Recv:13:32:09.180: FilamentAvailable_T1 = true

Send:13:32:09.180: N8 M82

Recv:13:32:09.195: ok

Send:13:32:09.195: N9 G21 ; Use mm as unit

Recv:13:32:09.211: ok

Send:13:32:09.211: N10 M114

Exec:13:32:09.211: @getIP

Recv:13:32:09.234: X:0.00 Y:0.00 Z:0.00 E:0.00

Recv:13:32:09.234: MESH_BED_LEVELING:

Recv:13:32:09.234: Z:-0.72 E:0.00

Recv:13:32:09.235: Count X: 0.00 Y:0.00 Z:0.00 E:0.00

Recv:13:32:09.235: ok

Send:13:32:09.235: N11 M114

Exec:13:32:09.235: @startCodeProcessed

Send:13:32:09.235: M117 192.168.1.71:3344

Recv:13:32:09.270: X:0.00 Y:0.00 Z:0.00 E:0.00

Recv:13:32:09.270: MESH_BED_LEVELING:

Recv:13:32:09.270: Z:-0.72 E:0.00

Recv:13:32:09.270: Count X: 0.00 Y:0.00 Z:0.00 E:0.00

Recv:13:32:09.271: ok (2)

Server-Log endet wie folgt:

2023-11-18 13:33:31: start printjob Hank_v4 on printer M10
2023-11-18 13:33:31: Updating info for /var/lib/Repetier-Server/printer/M10/jobs/00000004_Hank_v4.g printer M10
2023-11-18 13:33:33: Time analysing /var/lib/Repetier-Server/printer/M10/jobs/00000004_Hank_v4.g:1775813 us

Wenn ich nur noch weiße Seiten erhalte, sehe ich im Websocket-Log nur noch dies:

{"action":"ping","data":{"source":"gui"},"printer":"","callback_id":39}

mit hochzählender Callback-ID.

Woran könnte das liegen?

Danke,

Patrick

pschlan · November 2023

Im Websocket-Log sehe ich auch eine solche Anforderung, die nie beantwortet wird:

{"action":"listPrinter","data":{},"printer":"","callback_id":33}

Nach einiger Zeit wird weiterhin die Websocket-Verbindung kurz unterbrochen und neu aufgebaut. Weiß nicht, ob das irgendwas hilft.

pschlan · November 2023

(gdb) info threads
  Id   Target Id                 Frame 
* 1    LWP 689 "RepetierServer"  0x00902446 in __syscall_cp_c ()
  2    LWP 708 "ResponseLogger"  0x00902444 in __syscall_cp_c ()
  3    LWP 709 "Check updates"   0x00902444 in __syscall_cp_c ()
  4    LWP 710 "PJM M10"         0x00902444 in __syscall_cp_c ()
  5    LWP 711 "WIFI_Watch"      0x00902444 in __syscall_cp_c ()
  6    LWP 716 "GlobalCloud"     0x00902444 in __syscall_cp_c ()
  7    LWP 717 "WorkDispatcher"  0x00902444 in __syscall_cp_c ()
  8    LWP 718 "IntWorkDisp"     0x00902444 in __syscall_cp_c ()
  9    LWP 719 "PRT M10"         0x00902444 in __syscall_cp_c ()
  10   LWP 720 "CronJobs"        0x00902444 in __syscall_cp_c ()
  11   LWP 722 "Websocket"       0x00902444 in __syscall_cp_c ()
  12   LWP 723 "Websocket"       0x00902444 in __syscall_cp_c ()
  13   LWP 724 "TCPServ~:]:3344" 0x008f4f76 in epoll_pwait ()
  14   LWP 733 "PRT M10"         0x008f4f76 in epoll_pwait ()
  15   LWP 1161 "Websocket"      0x00902444 in __syscall_cp_c ()
  16   LWP 1208 "Websocket"      0x00902444 in __syscall_cp_c ()
  17   LWP 1209 "Websocket"      0x00902444 in __syscall_cp_c ()
  18   LWP 1210 "Websocket"      0x00902444 in __syscall_cp_c ()
  19   LWP 1343 "Websocket"      0x00902444 in __syscall_cp_c ()
  20   LWP 2394 "Websocket"      0x00902444 in __syscall_cp_c ()
  21   LWP 2395 "Websocket"      0x00902444 in __syscall_cp_c ()
  22   LWP 3028 "Websocket"      0x00902444 in __syscall_cp_c ()
  23   LWP 3030 "Websocket"      0x00902444 in __syscall_cp_c ()
  24   LWP 3034 "Websocket"      0x00902444 in __syscall_cp_c ()
  25   LWP 3035 "Websocket"      0x00902444 in __syscall_cp_c ()
  26   LWP 3036 "Websocket"      0x00902444 in __syscall_cp_c ()
  27   LWP 3037 "Websocket"      0x00902444 in __syscall_cp_c ()
  28   LWP 3038 "Websocket"      0x00902444 in __syscall_cp_c ()
  29   LWP 3679 "Websocket"      0x00902444 in __syscall_cp_c ()
  30   LWP 3680 "Websocket"      0x00902444 in __syscall_cp_c ()
  31   LWP 3737 "Websocket"      0x00902444 in __syscall_cp_c ()
  32   LWP 3738 "Websocket"      0x00902444 in __syscall_cp_c ()
  33   LWP 4400 "Websocket"      0x00902444 in __syscall_cp_c ()
  34   LWP 4553 "Websocket"      0x00902444 in __syscall_cp_c ()
  35   LWP 4676 "Websocket"      0x00902444 in __syscall_cp_c ()
  36   LWP 4677 "Websocket"      0x00902444 in __syscall_cp_c ()
  37   LWP 4678 "Websocket"      0x00902444 in __syscall_cp_c ()
  38   LWP 4679 "Websocket"      0x00902444 in __syscall_cp_c ()
  39   LWP 4680 "Websocket"      0x00902444 in __syscall_cp_c ()
  40   LWP 4694 "Websocket"      0x00902444 in __syscall_cp_c ()
  41   LWP 4976 "Websocket"      0x00902444 in __syscall_cp_c ()
  42   LWP 4977 "Websocket"      0x00902444 in __syscall_cp_c ()
  43   LWP 4978 "Websocket"      0x00902444 in __syscall_cp_c ()
  44   LWP 4979 "Websocket"      0x00902444 in __syscall_cp_c ()
  45   LWP 4980 "Websocket"      0x00902444 in __syscall_cp_c ()
  46   LWP 5097 "Websocket"      0x00902444 in __syscall_cp_c ()
  47   LWP 5098 "wr_finished"    0x00902444 in __syscall_cp_c ()
  48   LWP 5099 "Websocket"      0x00902444 in __syscall_cp_c ()
(gdb) bt
#0  0x00902446 in __syscall_cp_c ()
#1  0x0090940e in __sigtimedwait_time64 ()
#2  0x008fd8a8 in sigwait ()
#3  0x0001dbd6 in repetier::RepetierServerApplication::main(std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > const&) ()
#4  0x003c2a06 in Poco::Util::Application::run() ()
#5  0x0001a5b6 in main ()
(gdb) thread 4
[Switching to thread 4 (LWP 710)]
#0  0x00902444 in __syscall_cp_c ()
(gdb) bt
#0  0x00902444 in __syscall_cp_c ()
#1  0x00909da8 in __timedwait_cp ()
#2  0x00902958 in __pthread_cond_timedwait_time64 ()
#3  0x00000000 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb) thread 14
[Switching to thread 14 (LWP 733)]
#0  0x008f4f76 in epoll_pwait ()
(gdb) bt
#0  0x008f4f76 in epoll_pwait ()
#1  0x008f4f9c in epoll_wait ()
#2  0x00177676 in boost::asio::detail::epoll_reactor::run(long, boost::asio::detail::op_queue<boost::asio::detail::scheduler_operation>&) ()
#3  0x0017c848 in boost::asio::detail::scheduler::run(boost::system::error_code&) ()
#4  0x0017cc1c in boost::asio::io_context::run() ()
#5  0x0068207e in thread_proxy ()
#6  0x00902e7c in start ()
#7  0x00909f0c in __clone ()
#8  0x00909f0c in __clone ()
#9  0x00909f0c in __clone ()
#10 0x00909f0c in __clone ()
#11 0x00909f0c in __clone ()
#12 0x00909f0c in __clone ()
#13 0x00909f0c in __clone ()
#14 0x00909f0c in __clone ()
#15 0x00909f0c in __clone ()
#16 0x00909f0c in __clone ()
#17 0x00909f0c in __clone ()
#18 0x00909f0c in __clone ()
#19 0x00909f0c in __clone ()
#20 0x00909f0c in __clone ()
#21 0x00909f0c in __clone ()
#22 0x00909f0c in __clone ()
#23 0x00909f0c in __clone ()
#24 0x00909f0c in __clone ()
#25 0x00909f0c in __clone ()
#26 0x00909f0c in __clone ()
#27 0x00909f0c in __clone ()
#28 0x00909f0c in __clone ()
#29 0x00909f0c in __clone ()
#30 0x00909f0c in __clone ()
#31 0x00909f0c in __clone ()
#32 0x00909f0c in __clone ()
#33 0x00909f0c in __clone ()
#34 0x00909f0c in __clone ()
#35 0x00909f0c in __clone ()
#36 0x00909f0c in __clone ()
#37 0x00909f0c in __clone ()
#38 0x00909f0c in __clone ()
#39 0x00909f0c in __clone ()
#40 0x00909f0c in __clone ()
#41 0x00909f0c in __clone ()
#42 0x00909f0c in __clone ()
#43 0x00909f0c in __clone ()
#44 0x00909f0c in __clone ()
#45 0x00909f0c in __clone ()
#46 0x00909f0c in __clone ()
#47 0x00909f0c in __clone ()
#48 0x00909f0c in __clone ()
#49 0x00909f0c in __clone ()
#50 0x00909f0c in __clone ()
#51 0x00909f0c in __clone ()
#52 0x00909f0c in __clone ()
#53 0x00909f0c in __clone ()
#54 0x00909f0c in __clone ()
#55 0x00909f0c in __clone ()
--Type <RET> for more, q to quit, c to continue without paging-- 
#56 0x00909f0c in __clone ()
#57 0x00909f0c in __clone ()
#58 0x00909f0c in __clone ()
#59 0x00909f0c in __clone ()
#60 0x00909f0c in __clone ()
#61 0x00909f0c in __clone ()
#62 0x00909f0c in __clone ()
#63 0x00909f0c in __clone ()
#64 0x00909f0c in __clone ()
#65 0x00909f0c in __clone ()
#66 0x00909f0c in __clone ()
#67 0x00909f0c in __clone ()
#68 0x00909f0c in __clone ()
#69 0x00909f0c in __clone ()
#70 0x00909f0c in __clone ()
#71 0x00909f0c in __clone ()
#72 0x00909f0c in __clone ()
#73 0x00909f0c in __clone ()
#74 0x00909f0c in __clone ()
#75 0x00909f0c in __clone ()
#76 0x00909f0c in __clone ()
#77 0x00909f0c in __clone ()
#78 0x00909f0c in __clone ()
#79 0x00909f0c in __clone ()
#80 0x00909f0c in __clone ()
#81 0x00909f0c in __clone ()
#82 0x00909f0c in __clone ()
#83 0x00909f0c in __clone ()
#84 0x00909f0c in __clone ()
#85 0x00909f0c in __clone ()
#86 0x00909f0c in __clone ()
#87 0x00909f0c in __clone ()
#88 0x00909f0c in __clone ()
#89 0x00909f0c in __clone ()
#90 0x00909f0c in __clone ()
#91 0x00909f0c in __clone ()
#92 0x00909f0c in __clone ()
#93 0x00909f0c in __clone ()
#94 0x00909f0c in __clone ()
#95 0x00909f0c in __clone ()
#96 0x00909f0c in __clone ()
#97 0x00909f0c in __clone ()
#98 0x00909f0c in __clone ()
#99 0x00909f0c in __clone ()
#100 0x00909f0c in __clone ()
#101 0x00909f0c in __clone ()
#102 0x00909f0c in __clone ()
#103 0x00909f0c in __clone ()
#104 0x00909f0c in __clone ()
#105 0x00909f0c in __clone ()
#106 0x00909f0c in __clone ()
#107 0x00909f0c in __clone ()
#108 0x00909f0c in __clone ()
#109 0x00909f0c in __clone ()
(geht ewig so weiter)

pschlan · November 2023

Exemplarischer Websocket-Thread:

(gdb) thread 44
[Switching to thread 44 (LWP 4979)]
#0  0x00902444 in __syscall_cp_c ()
(gdb) bt
#0  0x00902444 in __syscall_cp_c ()
#1  0x00909da8 in __timedwait_cp ()
#2  0x00909e2c in __timedwait ()
#3  0x0090369e in __pthread_mutex_timedlock_time64 ()
#4  0x0006cc84 in boost::mutex::lock() ()
#5  0x00189c1e in repetier::PrinterState::fillJSONObject(rapidjson::GenericObject<false, rapidjson::GenericValue<rapidjson::UTF8<char>, rapidjson::StdAllocator<char, repetier::json::RSMemoryAllocator> > >, rapidjson::StdAllocator<char, repetier::json::RSMemoryAllocator>&, bool) ()
#6  0x00039bf0 in repetier::ActionHandler::actionStateList(repetier::AccessContext&, rapidjson::GenericDocument<rapidjson::UTF8<char>, rapidjson::StdAllocator<char, repetier::json::RSMemoryAllocator>, repetier::json::RSMemoryAllocator>&, rapidjson::GenericDocument<rapidjson::UTF8<char>, rapidjson::StdAllocator<char, repetier::json::RSMemoryAllocator>, repetier::json::RSMemoryAllocator>&) ()
#7  0x00039f96 in repetier::ActionHandler::dispatch(repetier::AccessContext&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&, rapidjson::GenericDocument<rapidjson::UTF8<char>, rapidjson::StdAllocator<char, repetier::json::RSMemoryAllocator>, repetier::json::RSMemoryAllocator>&, rapidjson::GenericDocument<rapidjson::UTF8<char>, rapidjson::StdAllocator<char, repetier::json::RSMemoryAllocator>, repetier::json::RSMemoryAllocator>&, repetier::LuaExtension*) ()
#8  0x00266274 in repetier::WebSocketRequestHandler::handleRequest(repetier::RequestContext&) ()
#9  0x00274244 in repetier::MainRequestHandler::handleRequest(Poco::Net::HTTPServerRequest&, Poco::Net::HTTPServerResponse&) ()
#10 0x00399b7e in Poco::Net::HTTPServerConnection::run() ()
#11 0x0038e730 in Poco::Net::TCPServerConnection::start() ()
#12 0x0038eb74 in Poco::Net::TCPServerDispatcher::run() ()
#13 0x0089f284 in Poco::PooledThread::run() ()
#14 0x00319b62 in Poco::ThreadImpl::runnableEntry(void*) ()
#15 0x00902e7c in start ()
#16 0x00909f0c in __clone ()
#17 0x00909f0c in __clone ()
#18 0x00909f0c in __clone ()
#19 0x00909f0c in __clone ()
#20 0x00909f0c in __clone ()
#21 0x00909f0c in __clone ()
#22 0x00909f0c in __clone ()
#23 0x00909f0c in __clone ()
#24 0x00909f0c in __clone ()
#25 0x00909f0c in __clone ()
#26 0x00909f0c in __clone ()
#27 0x00909f0c in __clone ()
#28 0x00909f0c in __clone ()
#29 0x00909f0c in __clone ()
#30 0x00909f0c in __clone ()
#31 0x00909f0c in __clone ()
#32 0x00909f0c in __clone ()
#33 0x00909f0c in __clone ()
#34 0x00909f0c in __clone ()
#35 0x00909f0c in __clone ()
#36 0x00909f0c in __clone ()
#37 0x00909f0c in __clone ()
#38 0x00909f0c in __clone ()
#39 0x00909f0c in __clone ()
#40 0x00909f0c in __clone ()
#41 0x00909f0c in __clone ()
#42 0x00909f0c in __clone ()
#43 0x00909f0c in __clone ()
#44 0x00909f0c in __clone ()
#45 0x00909f0c in __clone ()
#46 0x00909f0c in __clone ()
#47 0x00909f0c in __clone ()
#48 0x00909f0c in __clone ()
#49 0x00909f0c in __clone ()
#50 0x00909f0c in __clone ()

Sieht für mich nach einem Deadlock aus. Die Websocket-Threads wollen wohl die Druckerliste erzeugen, aber hängen dann beim Acquirer einer Mutex fest...

Das erklärt dann auch, warum der Browser keine Antworten mehr erhählt nach dem Anfordern der Druckerliste und irgendwann eine neue Verbindung aufbaut. (Und die Anzahl der Websocket-Threads fortwährend wächst.)

pschlan · November 2023

Thread 9 (PRT M10) hängt auch im Lock-Acquire. Erklärt dann auch, warum nicht gedruckt wird. Ich frage mich jetzt nur, wer den Lock hält und somit alles zum Erliegen bringt.

(gdb) thread 9
[Switching to thread 9 (LWP 719)]
#0  0x00902444 in __syscall_cp_c ()
(gdb) bt
#0  0x00902444 in __syscall_cp_c ()
#1  0x00909da8 in __timedwait_cp ()
#2  0x00909e2c in __timedwait ()
#3  0x0090369e in __pthread_mutex_timedlock_time64 ()
#4  0x0006cc84 in boost::mutex::lock() ()
#5  0x00124728 in repetier::Printer::injectManualInCategoryFront(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&, bool, std::deque<std::shared_ptr<repetier::GCode>, std::allocator<std::shared_ptr<repetier::GCode> > >&) ()
#6  0x0012cc16 in repetier::Printer::enrichManualWithReplacementsFront(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&, bool, int, std::deque<std::shared_ptr<repetier::GCode>, std::allocator<std::shared_ptr<repetier::GCode> > >&) ()
#7  0x0012cdf8 in repetier::Printer::injectManualCommandFirst(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, bool) ()
#8  0x00114d9c in repetier::PauseHandler::startPause(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >) ()
#9  0x0018f766 in repetier::PrinterState::analyze(repetier::GCode&, bool) ()
#10 0x00135aaa in repetier::Printer::trySendNextLine() ()
#11 0x0013a042 in repetier::Printer::runConnected() ()
#12 0x0013a2c8 in repetier::Printer::run() ()
#13 0x0068207e in thread_proxy ()
#14 0x00902e7c in start ()
#15 0x00909f0c in __clone ()

Repetier · November 2023

Gute Analyse!

Hast du zufällig ein M601 in deinem G-Code? Habe erst gestern einen deadlock bei M601 gefunden der exact diesen Backtrace hat. In dem fall bitte nightly oder dev version installieren (installDev bei neueren images). Oder @pause stadt M601 nutzen, was der code der den deadlock erzeugt nämlich macht.

pschlan · November 2023

Danke für die schnelle Antwort!

Im Gcode selbst sehe ich keinen M601, aber in der Printer-Config:

Kann es damit zu tun haben?

pschlan · November 2023

Habe mal auf die Dev-Version aktualisiert. Damit hängt es sich nicht mehr auf und ich kann den Drucker ent-pausieren nachdem ich den Druck gestartet habe.

Jetzt frage ich mich nur, warum M601 als Start-Script in der Drucker-Config hinterlegt wurde vom Hersteller. Damit pausiert er ja beim Start erstmal direkt?

Die Config war in der vorherig genutzten Repetier-Server-Version gleich, da pausierte der Drucker aber nicht automatisch beim Starten eines Auftrags. Hat sich hier etwas geändert im Verhalten?

Repetier · November 2023

In unserem Pause Skript steht das normal nciht drin, also keine Ahnung wo es bei dir her kam. Pause am start macht in der Tat keinen sinn.

Repetier Server "hängt" nach Druck-Start

Comments