TheSpaghettiDetective / obico-server

Obico is a community-built, open-source smart 3D printing platform used by makers, enthusiasts, and tinkerers around the world.
https://obico.io
GNU Affero General Public License v3.0
1.5k stars 299 forks source link

plugin delays shutdown #272

Closed vogler closed 4 years ago

vogler commented 4 years ago

There was no print, still the plugin delays quitting the server:

2020-08-18 14:31:34,741 - octoprint.plugins.thespaghettidetective - WARNING - WS tunnel closed. Restarting janus tunnel.
2020-08-18 14:31:34,745 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 0.615910 seconds: Janus WS connection closed!
2020-08-18 14:31:35,362 - octoprint.plugins.thespaghettidetective - WARNING - WS tunnel closed. Restarting janus tunnel.
2020-08-18 14:31:35,367 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 0.771954 seconds: Janus WS connection closed!
2020-08-18 14:31:36,140 - octoprint.plugins.thespaghettidetective - WARNING - WS tunnel closed. Restarting janus tunnel.
2020-08-18 14:31:36,144 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 2.286453 seconds: Janus WS connection closed!
2020-08-18 14:31:38,434 - octoprint.plugins.thespaghettidetective - WARNING - WS tunnel closed. Restarting janus tunnel.
2020-08-18 14:31:38,437 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 2.366757 seconds: Janus WS connection closed!
2020-08-18 14:31:40,807 - octoprint.plugins.thespaghettidetective - WARNING - WS tunnel closed. Restarting janus tunnel.
2020-08-18 14:31:40,811 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 6.396760 seconds: Janus WS connection closed!
2020-08-18 14:31:47,211 - octoprint.plugins.thespaghettidetective - WARNING - WS tunnel closed. Restarting janus tunnel.
kennethjiang commented 4 years ago

Can you give us more details on how this problem can be reproduced?

vogler commented 4 years ago

It happens every time I ctrl-c a running ./venv/bin/octoprint serve. It's also trying to do something with ffmpeg every shutdown. The times differ, just now it wasn't as long:

2020-08-18 18:40:35,989 - octoprint.server.heartbeat - INFO - Server heartbeat <3
^C2020-08-18 18:54:05,200 - octoprint.server - INFO - Shutting down...
2020-08-18 18:54:05,229 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 0.237707 seconds: Janus WS connection closed!
2020-08-18 18:54:05,350 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 0.311447 seconds: Janus quit! This should not happen. Exit code: -2
2020-08-18 18:54:05,373 - octoprint.plugins.thespaghettidetective - ERROR - STDERR:
ffmpeg version N-94817-g8a1f0cb-tsd.0.1 Copyright (c) 2000-2019 the FFmpeg developers
  built with gcc 4.9.2 (Raspbian 4.9.2-10)
  configuration: --prefix=/usr --extra-version=tsd.0.1 --libdir=/usr/lib/arm-linux-gnueabihf --incdir=/usr/include/arm-linux-gnueabihf --arch=armhf --enable-small --enable-gpl --enable-mmal --enable-omx --enable-omx-rpi
  libavutil      56. 35.100 / 56. 35.100
  libavcodec     58. 56.101 / 58. 56.101
  libavformat    58. 32.104 / 58. 32.104
  libavdevice    58.  9.100 / 58.  9.100
  libavfilter     7. 58.102 /  7. 58.102
  libswscale      5.  6.100 /  5.  6.100
  libswresample   3.  6.100 /  3.  6.100
  libpostproc    55.  6.100 / 55.  6.100
Input #0, mpjpeg, from 'http://rpi4:8090/?action=stream':
  Duration: N/A, bitrate: N/A
    Stream #0:0: Video: mjpeg, yuvj422p(pc, bt470bg/unknown/unknown), 640x480, 25 tbr, 25 tbn, 25 tbc
Stream mapping:
  Stream #0:0 -> #0:0 (mjpeg (native) -> h264 (h264_omx))
Press [q] to stop, [?] for help
[swscaler @ 0x2c52ab0] deprecated pixel format used, make sure you did set range correctly
[h264_omx @ 0x2c10bf0] Using OMX.broadcom.video_encode
Output #0, rtp, to 'rtp://127.0.0.1:8004?pkt_size=1300':
  Metadata:
    encoder         : Lavf58.32.104
frame=70892 fps=5.0 q=-0.0 Lsize=  350351kB time=00:47:15.64 bitrate=1012.1kbits/s speed=0.199x
video:346311kB audio:0kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: 1.166728%
Exiting normally, received signal 2.

2020-08-18 18:54:05,468 - octoprint.plugins.thespaghettidetective - WARNING - WS tunnel closed. Restarting janus tunnel.
2020-08-18 18:54:05,474 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 0.290155 seconds: Janus WS connection closed!
2020-08-18 18:54:05,767 - octoprint.plugins.thespaghettidetective - WARNING - WS tunnel closed. Restarting janus tunnel.
2020-08-18 18:54:05,774 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 0.647137 seconds: Janus WS connection closed!
2020-08-18 18:54:06,173 - octoprint.server - INFO - Calling on_shutdown on plugins
2020-08-18 18:54:06,176 - octoprint.events - INFO - Processing shutdown event, this will be our last event
2020-08-18 18:54:06,189 - octoprint.events - INFO - Event loop shut down
2020-08-18 18:54:06,423 - octoprint.plugins.thespaghettidetective - WARNING - WS tunnel closed. Restarting janus tunnel.
2020-08-18 18:54:06,426 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 2.098382 seconds: Janus WS connection closed!
Failed to start webcamd.service: Unit webcamd.service not found.
2020-08-18 18:54:16,771 - octoprint.server - INFO - Goodbye!

Environment:

2020-08-18 19:02:20,028 - octoprint.startup - INFO - Starting OctoPrint 1.4.2
...
2020-08-18 19:02:28,135 - octoprint.plugin.core - INFO - 43 plugin(s) registered with the system:
|  Access Anywhere - The Spaghetti Detective (1.3.3) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_thespaghettidetective
|  Action Command Notification Support (bundled) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint/plugins/action_command_notification
|  Action Command Prompt Support (bundled) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint/plugins/action_command_prompt
|  Announcement Plugin (bundled) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint/plugins/announcements
|  Anonymous Usage Tracking (bundled) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint/plugins/tracking
|  Application Keys Plugin (bundled) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint/plugins/appkeys
|  Autoscroll (0.0.3) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_autoscroll
|  Autoselect Plugin (0.3.0) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_autoselect
|  Backup & Restore (bundled) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint/plugins/backup
|  Cancel Objects (0.4.3) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_cancelobject
|  Consolidated Tabs (0.0.8) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_consolidatedtabs
|  Continuous Print (1.0.3) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/continuousprint
|  Core Wizard (bundled) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint/plugins/corewizard
| *Cost Estimation (2.1.3) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_costestimation
| !Dashboard (1.14.0) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_dashboard
|  Discovery (bundled) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint/plugins/discovery
|  DisplayLayerProgress Plugin (1.23.0) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_DisplayLayerProgress
|  Error Tracking (bundled) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint/plugins/errortracking
|  Filament Manager (0.5.3) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_filamentmanager
|  File Check (2020.8.7) (bundled) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_file_check
|  FileManager (0.1.4) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_filemanager
|  Firmware Check (2020.6.22) (bundled) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_firmware_check
|  GCode Viewer (bundled) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint/plugins/gcodeviewer
| #GcodeEditor (0.2.8) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_GcodeEditor
|  Logging (bundled) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint/plugins/logging
|  Login UI (bundled) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint/plugins/loginui
|  MQTT (0.8.7) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_mqtt
|  Octolapse (0.4.0) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_octolapse
|  Pi Support Plugin (bundled) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint/plugins/pi_support
|  Plugin Manager (bundled) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint/plugins/pluginmanager
|  Preheat Button (0.5.1) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_preheat
|  PrettyGCode (1.2) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_prettygcode
|  PrintJobHistory (1.7.0) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_PrintJobHistory
|  PrintTimeGenius Plugin (2.2.5) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_PrintTimeGenius
|  PrusaSlicer Thumbnails (0.1.2) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_prusaslicerthumbnails
|  Resource Monitor (0.2.5) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_resource_monitor
|  Software Update (bundled) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint/plugins/softwareupdate
|  STL Viewer (0.4.2) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_stlviewer
|  Tab Order (0.5.10) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_taborder
|  Tasmota-MQTT (0.3.6) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_tasmota_mqtt
|  Terminal Commands Extended (0.1.5) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_terminalcommandsextended
|  Ultimaker Format Package (0.1.9) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint_ultimakerformatpackage
|  Virtual Printer (bundled) = /home/pi/OctoPrint/venv/lib/python3.7/site-packages/octoprint/plugins/virtual_printer
Prefix legend: ! = disabled, # = blacklisted, * = incompatible
2020-08-18 19:02:28,153 - octoprint.environment - INFO - Detected environment is Python 3.7.3 under Linux (linux). Details:
|  hardware:
|      cores: 4
|      freq: 1500.0
|      ram: 3981672448
|  os:
|      id: linux
|      platform: linux
|  plugins:
|      pi_support:
|          model: Raspberry Pi 4 Model B Rev 1.1
|  python:
|      pip: 20.2.2
|      version: 3.7.3
|      virtualenv: /home/pi/OctoPrint/venv
kennethjiang commented 4 years ago

If I understand the problem correctly, in the 2nd log file you posted, there was an extra ~1s delay in shutting down the server? But you this can sometimes be longer?

I suspect this has to do with ctrl-c sends SIGINT, whereas when the service is shut down using systemctl SIGTERM is sent.

Any reason why you want to shut down the service manually?

vogler commented 4 years ago

there was an extra ~1s delay in shutting down the server?

Could be 11s since there's no more timestamp after the last thespaghettidetective output.

Any reason why you want to shut down the service manually?

I was working on some plugin and wanted to reload. Did not make a service of it yet since I just started using OctoPrint. What's your proposed alternative? Keeping journalctl -f -u open and doing systemctl restart? Shouldn't matter how it's run, no?

I suspect this has to do with ctrl-c sends SIGINT, whereas when the service is shut down using systemctl SIGTERM is sent.

Forgot that ^\ is SIGQUIT. That shut it down instantly, but now (maybe unrelated?) it already has problems upon start. kill (SIGTERM) seems to not produce the delays, but maybe it would in the initial setting.

2020-08-19 09:42:37,233 - octoprint.util.comm - INFO - Changing monitoring state from "Detecting serial connection" to "Error: No more candidates to test, and no working port/baudrate combination detected."
2020-08-19 09:42:37,258 - octoprint.util.comm - INFO - Changing monitoring state from "Error: No more candidates to test, and no working port/baudrate combination detected." to "Offline (Error: No more candidates to test, and no working port/baudrate combination detected.)"
2020-08-19 09:42:37,312 - octoprint.plugins.action_command_notification - INFO - Notifications cleared
Failed to stop webcamd.service: Unit webcamd.service not loaded.
mmal: mmal_vc_component_create: failed to create component 'vc.ril.camera' (1:ENOMEM)
mmal: mmal_component_create_core: could not create component 'vc.ril.camera' (1)
2020-08-19 09:42:40,645 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 0.210108 seconds: Janus quit! This should not happen. Exit code: 1
2020-08-19 09:42:41,634 - backoff - INFO - Backing off start_gst(...) for 1.0s (Exception: GST failed. Exit code: 1)
2020-08-19 09:42:43,714 - backoff - INFO - Backing off start_gst(...) for 2.0s (Exception: GST failed. Exit code: 1)
2020-08-19 09:42:46,666 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 0.269500 seconds: Janus quit! This should not happen. Exit code: 1
2020-08-19 09:42:46,761 - backoff - INFO - Backing off start_gst(...) for 4.0s (Exception: GST failed. Exit code: 1)
2020-08-19 09:42:48,061 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 0.533063 seconds: Janus quit! This should not happen. Exit code: 1
2020-08-19 09:42:51,810 - backoff - INFO - Backing off start_gst(...) for 8.0s (Exception: GST failed. Exit code: 1)
2020-08-19 09:42:53,171 - octoprint.server.preemptive_cache - INFO - ... done in 18.36s
2020-08-19 09:42:53,335 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 1.024876 seconds: Janus quit! This should not happen. Exit code: 1
2020-08-19 09:42:58,955 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 5.372018 seconds: Janus quit! This should not happen. Exit code: 1
2020-08-19 09:43:00,841 - backoff - INFO - Backing off start_gst(...) for 16.0s (Exception: GST failed. Exit code: 1)
2020-08-19 09:43:08,266 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 6.235405 seconds: Janus quit! This should not happen. Exit code: 1
2020-08-19 09:43:17,871 - backoff - ERROR - Giving up start_gst(...) after 6 tries (Exception: GST failed. Exit code: 1)
2020-08-19 09:43:18,097 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 15.749099 seconds: Janus quit! This should not happen. Exit code: 1
Failed to start webcamd.service: Unit webcamd.service not found.
2020-08-19 09:43:38,645 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 42.667490 seconds: Janus quit! This should not happen. Exit code: 1
2020-08-19 09:44:23,774 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 37.310497 seconds: Janus quit! This should not happen. Exit code: 1
2020-08-19 09:45:03,853 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 74.186593 seconds: Janus quit! This should not happen. Exit code: 1
2020-08-19 09:46:19,882 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 79.919312 seconds: Janus quit! This should not happen. Exit code: 1
2020-08-19 09:47:43,095 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 69.051067 seconds: Janus quit! This should not happen. Exit code: 1
...
kennethjiang commented 4 years ago

Can you do a few more test to confirm if there is a difference between SIGINT and SIGTERM?

vogler commented 4 years ago

SIGINT results in the ffmpeg call and sometimes additional

2020-08-19 16:26:27,071 - octoprint.plugins.thespaghettidetective - ERROR - Backing off 36.456254 seconds: Janus quit! This should not happen. Exit code: -2

Note the Exit code: -2 instead of 1.

What worries me more now is the messages during startup: Janus quit! This should not happen..

kennethjiang commented 4 years ago

Sorry for the delay.

Janus quit! This should not happen is just a misfired error message when OctoPrint is shutdown in an expected way. I don't think it causes any harm unless there is evidence why it does.

I just tested it myself. You can actually press ctrl-c twice to get it exit immediately. I hope this is a good enough workaround. But if you want you can submit a PR for a proper fix and I'll be happy to merge it.

vogler commented 4 years ago

Ok, thanks, then I'll just ignore those messages.