Octoprint: Random crashing of the octoprint server
What were you doing?
When running a variety of prints, my installation of the OctoPrint server will crash. If you use a web browser you are greeted with a message of please SSH into the pi and restart the octopi service and to check out the logs. In the logs the only things logged are some connection issues with one of my plugin's (octoprint anywhere) ability to reach the internet, then the registering of the rebooting of the Pi.
I usually just power cycle the PI to reset everything rather than SSH in.
This is often accompanied by a crashing of the MPEG steamer service in advance of the Octoprint service crash, but not always. I am using a systemD script to start and stop the MPEG steamer.
My printer (a MBI replicator 2) will just hang waiting for more commands over the serial connection, that is now lost due to the octoprint service crash. I have GPX installed.
I have been dealing with this problem almost since I got the octoprint and the GPX plugin stable close to a year ago.
The first crash happens several hours after I started a print and left for the evening. This is the last message logged before the log shows me starting the Pi the next day when I find it crashed: 2018-02-11 21:20:24,394 - anywhere - WARNING - Not connected to server ws or connection lost
I started another print and had the same crash occur 2 hours later as the print is progressing. The crash stamp is 2018-02-12 12:52:20,990.
Plugins enabled:
GPX
Cura Engine
Print History Plugin
Octoprint Anywhere
What did you expect to happen?
The print to finish
What happened instead?
The printer stopped receiving commands from Octoprint and sat there until a human canceled the print and rebooted octoprint.
Did the same happen when running OctoPrint in safe mode?
I have not been able to reproduce the bug in safe mode as this has happened probably 1-4 times a month and I don't want to always be running is safe mode.
Version of OctoPrint
OctoPrint 1.3.6 running on OctoPi 0.13.0
Operating System running OctoPrint
OctoPi 0.13.0
Printer model & used firmware incl. version
MBI replicator 2 with HBP running sailfish 7.7
Browser and Version of Browser, Operating System running Browser
Windows 10 running Chrome Version 64.0.3282.167 (Official Build) (64-bit)
Link to octoprint.log
plugin_GPX.log
octoprint.2018-02-12.log
Link to contents of terminal tab or serial.log
Serial.log not enabled, contents of terminal tab don't show anything of value as this crash occurred 3 days and several prints ago. Will update ticket if I can get them.
Link to contents of Javascript console in the browser
Not a UI or web interface issue.
The Contribution Guidelines tell you where to find that.]
Screenshot(s)/video(s) showing the problem:
N/A
I have read the FAQ.
stidf
All 24 comments
I usually just power cycle the PI to reset everything rather than SSH in.
You definitely should stop doing that immediately, you risk file system corruption that way and that can cause a lot of issues including crashes. Honestly, since you've been doing that for a while I'd strongly recommend to reflash with a clean image since there are probably a lot of things now broken on that image messing with its general operation. As a rule of thumb, never just cut power to a running Linux system, it's bad news, and it's especially bad news with the Raspberry Pi.
When it crashes and you do SSH into it, I take it the OctoPrint process is no longer running when you check that via ps -ef | grep -i octoprint? Since your webcam server also at least sometimes crashes, it sounds less than an application specific issue to me and more like a general stability issue. The question is why.
I'd recommend to secure the output of dmesg and the contents of /var/log/syslog the next time it happens, maybe that will give us a hint. Right now there's sadly not much to go on in order to analyse this.
It might also be worth a shot to have OctoPrint run directly from within a screen instance instead of as a service:
sudo apt-get update && sudo apt-get install screen
sudo service octoprint stop
screen
/home/pi/oprint/bin/octoprint serve
That way everything printed to stdout (even a segfault of the underlying python process) will be recoverable by simply reattaching to the screen session after a crash (screen -x).
This huge block of \0 bytes in your log here:
00083190: 2E 31 36 38 2E 32 2E 31 39 36 0A 32 30 31 38 2D .168.2.196.2018-
000831a0: 30 32 2D 31 32 20 31 30 3A 33 37 3A 33 38 2C 33 02-12.10:37:38,3
000831b0: 35 35 20 2D 20 6F 63 74 6F 70 72 69 6E 74 2E 75 55.-.octoprint.u
000831c0: 74 69 6C 2E 63 6F 6D 6D 20 2D 20 49 4E 46 4F 20 til.comm.-.INFO.
000831d0: 2D 20 4D 31 31 30 20 64 65 74 65 63 74 65 64 2C -.M110.detected,
000831e0: 20 73 65 74 74 69 6E 67 20 63 75 72 72 65 6E 74 .setting.current
000831f0: 20 6C 69 6E 65 20 6E 75 6D 62 65 72 20 74 6F 20 .line.number.to.
00083200: 30 0A 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0...............
00083210: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083220: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083230: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083240: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083250: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083260: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083270: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083280: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083290: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
000832a0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
000832b0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
000832c0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
000832d0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
000832e0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
000832f0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083300: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083310: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083320: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083330: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083340: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083350: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083360: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083370: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083380: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083390: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
000833a0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
000833b0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
000833c0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
000833d0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
000833e0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
000833f0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083400: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083410: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083420: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083430: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00083440: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 32 ...............2
00083450: 30 31 38 2D 30 32 2D 31 32 20 31 30 3A 33 36 3A 018-02-12.10:36:
00083460: 32 35 2C 32 34 31 20 2D 20 6F 63 74 6F 70 72 69 25,241.-.octopri
00083470: 6E 74 2E 73 74 61 72 74 75 70 20 2D 20 49 4E 46 nt.startup.-.INF
00083480: 4F 20 2D 20 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A O.-.************
00083490: 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A ****************
000834a0: 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A ****************
000834b0: 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A ****************
000834c0: 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A ****************
000834d0: 2A 2A 0A 32 30 31 38 2D 30 32 2D 31 32 20 31 30 **.2018-02-12.10
000834e0: 3A 33 36 3A 32 35 2C 32 34 34 20 2D 20 6F 63 74 :36:25,244.-.oct
000834f0: 6F 70 72 69 6E 74 2E 73 74 61 72 74 75 70 20 2D oprint.startup.-
00083500: 20 49 4E 46 4F 20 2D 20 53 74 61 72 74 69 6E 67 .INFO.-.Starting
00083510: 20 4F 63 74 6F 50 72 69 6E 74 20 31 2E 33 2E 36 .OctoPrint.1.3.6
00083520: 0A 32 30 31 38 2D 30 32 2D 31 32 20 31 30 3A 33 .2018-02-12.10:3
00083530: 36 3A 32 35 2C 32 34 34 20 2D 20 6F 63 74 6F 70 6:25,244.-.octop
00083540: 72 69 6E 74 2E 73 74 61 72 74 75 70 20 2D 20 49 rint.startup.-.I
00083550: 4E 46 4F 20 2D 20 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A NFO.-.**********
00083560: 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A ****************
00083570: 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A ****************
00083580: 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A ****************
00083590: 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A 2A ****************
indicates log corruption, so just cutting power definitely let to data loss at least once here.
I also see that your instance isn't connected to the internet, but you still have the OctoPrint Anywhere plugin installed, which strikes me as a bit odd considering that that obviously needs a working net connection, hence the ton of errors in the log.
And something's up with your webcam configuration as well, hence the huge numbers of capture failures.
foosel
on 14 Feb 2018
Well this is why I am here.
The Pi is definitely connected to the internet. The office router sees both its WiFi connection and ethernet connections. Plus the router software shows that the Pi was definitely an active device on the day in question.
Sounds like the good old nuke and pave approach is the best way forward here. Not only for the power cycling issues. It will also likely fix some of the lingering silly things I did while trying to setup the web cam, before going to the systemD script. Blindly following setup guides on the internet is not the best of ideas, especially when your command line fu is weak. These things may or may not be affecting connections and the managing of port access.
Is there any logs of value that can/should be acquired now 3 days and several prints later before I re-image?
stidf
on 14 Feb 2018
I don't think so. Since we are basically looking at a possibly corrupted system, it would make more sense in any case to reimage and see if that makes the problems go away. And if not we have new logs.
About your net connectivity, OctoPrint determines that by trying to connect to a server on the net. By default that's Google's DNS at 8.8.8.8. Maybe it can't reach that for whatever reason but otherwise has perfect connectivity, in which case you should be able to simply configure a different IP on the net. Or alternatively just disable connectivity check, it's under Settings > Server.
foosel
on 14 Feb 2018
Thanks! I'll reopen the ticket if the problem comes back.
stidf
on 14 Feb 2018
So an update: It happened again. I reflashed and re-configured the octoprint install after downloading the latest version of octopi. Printer and print server were running fine since Saturday. The Pi and printer haven't lost power and been running more or less continuously since I reflashed the Pi. Last night I started a 24 hr print and when I checked on it this afternoon, it had crashed. Was working fine in the morning.
Attached are the logs.
Octoprint.log.2018-02-20.txt
Octoprint.log.2018-02-21.txt
Octoprint.log.current.txt
Output of dmesg: pi@mulePi:~/.octoprint/logs $ dmesg
[ 0.000000] Booting Linux on physical CPU 0x0
[ 0.000000] Linux version 4.9.28-v7+ (dc4@dc4-XPS13-9333) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611) ) #998 SMP Mon May 15 16:55:39 BST 2017
[ 0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
[ 0.000000] CPU: div instructions available: patching division code
[ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[ 0.000000] OF: fdt:Machine model: Raspberry Pi 3 Model B Rev 1.2
[ 0.000000] cma: Reserved 8 MiB at 0x36800000
[ 0.000000] Memory policy: Data cache writealloc
[ 0.000000] On node 0 totalpages: 225280
[ 0.000000] free_area_init_node: node 0, pgdat 80c6edc0, node_mem_map b603a000
[ 0.000000] Normal zone: 1980 pages used for memmap
[ 0.000000] Normal zone: 0 pages reserved
[ 0.000000] Normal zone: 225280 pages, LIFO batch:31
[ 0.000000] percpu: Embedded 14 pages/cpu @b5ff4000 s25600 r8192 d23552 u57344
[ 0.000000] pcpu-alloc: s25600 r8192 d23552 u57344 alloc=14*4096
[ 0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
[ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 223300
[ 0.000000] Kernel command line: 8250.nr_uarts=0 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3dc00000 vc_mem.mem_size=0x3f000000 dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 root=PARTUUID=538ad6ae-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
[ 0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes)
[ 0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[ 0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[ 0.000000] Memory: 871340K/901120K available (7168K kernel code, 483K rwdata, 2012K rodata, 1024K init, 778K bss, 21588K reserved, 8192K cma-reserved)
[ 0.000000] Virtual kernel memory layout:
vector : 0xffff0000 - 0xffff1000 ( 4 kB)
fixmap : 0xffc00000 - 0xfff00000 (3072 kB)
vmalloc : 0xb7800000 - 0xff800000 (1152 MB)
lowmem : 0x80000000 - 0xb7000000 ( 880 MB)
modules : 0x7f000000 - 0x80000000 ( 16 MB)
.text : 0x80008000 - 0x80800000 (8160 kB)
.init : 0x80b00000 - 0x80c00000 (1024 kB)
.data : 0x80c00000 - 0x80c78f94 ( 484 kB)
.bss : 0x80c7a000 - 0x80d3ca64 ( 779 kB)
[ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[ 0.000000] Hierarchical RCU implementation.
[ 0.000000] Build-time adjustment of leaf fanout to 32.
[ 0.000000] NR_IRQS:16 nr_irqs:16 16
[ 0.000000] arm_arch_timer: Architected cp15 timer(s) running at 19.20MHz (phys).
[ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
[ 0.000008] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[ 0.000024] Switching to timer-based delay loop, resolution 52ns
[ 0.000327] Console: colour dummy device 80x30
[ 0.001219] console [tty1] enabled
[ 0.001268] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[ 0.001339] pid_max: default: 32768 minimum: 301
[ 0.001706] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.001749] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.002775] Disabling cpuset control group subsystem
[ 0.002967] CPU: Testing write buffer coherency: ok
[ 0.003035] ftrace: allocating 22386 entries in 66 pages
[ 0.055973] CPU0: update cpu_capacity 1024
[ 0.056038] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[ 0.056134] Setting up static identity map for 0x100000 - 0x100034
[ 0.058358] CPU1: update cpu_capacity 1024
[ 0.058365] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[ 0.059080] CPU2: update cpu_capacity 1024
[ 0.059087] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[ 0.059751] CPU3: update cpu_capacity 1024
[ 0.059757] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[ 0.059840] Brought up 4 CPUs
[ 0.060013] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[ 0.060043] CPU: All CPU(s) started in HYP mode.
[ 0.060070] CPU: Virtualization extensions available.
[ 0.060883] devtmpfs: initialized
[ 0.071928] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
[ 0.072251] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[ 0.072313] futex hash table entries: 1024 (order: 4, 65536 bytes)
[ 0.072876] pinctrl core: initialized pinctrl subsystem
[ 0.073797] NET: Registered protocol family 16
[ 0.076065] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[ 0.084861] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[ 0.084910] hw-breakpoint: maximum watchpoint size is 8 bytes.
[ 0.085080] Serial: AMBA PL011 UART driver
[ 0.086965] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[ 0.087508] uart-pl011 3f201000.serial: could not find pctldev for node /soc/gpio@7e200000/uart0_pins, deferring probe
[ 0.156540] bcm2835-dma 3f007000.dma: DMA legacy API manager at b780f000, dmachans=0x1
[ 0.158398] SCSI subsystem initialized
[ 0.158580] usbcore: registered new interface driver usbfs
[ 0.158684] usbcore: registered new interface driver hub
[ 0.158798] usbcore: registered new device driver usb
[ 0.165522] raspberrypi-firmware soc:firmware: Attached to firmware from 2017-05-15 17:01
[ 0.166931] clocksource: Switched to clocksource arch_sys_counter
[ 0.213782] VFS: Disk quotas dquot_6.6.0
[ 0.213891] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[ 0.214117] FS-Cache: Loaded
[ 0.214381] CacheFiles: Loaded
[ 0.226568] NET: Registered protocol family 2
[ 0.227512] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[ 0.227650] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[ 0.227861] TCP: Hash tables configured (established 8192 bind 8192)
[ 0.227976] UDP hash table entries: 512 (order: 2, 16384 bytes)
[ 0.228043] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[ 0.228278] NET: Registered protocol family 1
[ 0.228712] RPC: Registered named UNIX socket transport module.
[ 0.228745] RPC: Registered udp transport module.
[ 0.228773] RPC: Registered tcp transport module.
[ 0.228801] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 0.229747] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[ 0.232055] workingset: timestamp_bits=14 max_order=18 bucket_order=4
[ 0.248118] FS-Cache: Netfs 'nfs' registered for caching
[ 0.249116] NFS: Registering the id_resolver key type
[ 0.249166] Key type id_resolver registered
[ 0.249194] Key type id_legacy registered
[ 0.251626] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251)
[ 0.251774] io scheduler noop registered
[ 0.251805] io scheduler deadline registered (default)
[ 0.252131] io scheduler cfq registered
[ 0.257807] BCM2708FB: allocated DMA memory f6910000
[ 0.257861] BCM2708FB: allocated DMA channel 0 @ b780f000
[ 0.266556] Console: switching to colour frame buffer device 82x26
[ 0.275012] bcm2835-rng 3f104000.rng: hwrng registered
[ 0.277413] vc-cma: Videocore CMA driver
[ 0.279628] vc-cma: vc_cma_base = 0x00000000
[ 0.281848] vc-cma: vc_cma_size = 0x00000000 (0 MiB)
[ 0.284105] vc-cma: vc_cma_initial = 0x00000000 (0 MiB)
[ 0.286512] vc-mem: phys_addr:0x00000000 mem_base=0x3dc00000 mem_size:0x3f000000(1008 MiB)
[ 0.306102] brd: module loaded
[ 0.317014] loop: module loaded
[ 0.319054] Loading iSCSI transport class v2.0-870.
[ 0.321612] usbcore: registered new interface driver smsc95xx
[ 0.323706] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[ 0.551881] Core Release: 2.80a
[ 0.553945] Setting default values for core params
[ 0.555990] Finished setting default values for core params
[ 0.758449] Using Buffer DMA mode
[ 0.760499] Periodic Transfer Interrupt Enhancement - disabled
[ 0.762645] Multiprocessor Interrupt Enhancement - disabled
[ 0.764806] OTG VER PARAM: 0, OTG VER FLAG: 0
[ 0.767018] Dedicated Tx FIFOs mode
[ 0.769477] WARN::dwc_otg_hcd_init:1034: FIQ DMA bounce buffers: virt = 0xb6904000 dma = 0xf6904000 len=9024
[ 0.773913] FIQ FSM acceleration enabled for :
Non-periodic Split Transactions
Periodic Split Transactions
High-Speed Isochronous Endpoints
Interrupt/Control Split Transaction hack enabled
[ 0.785250] dwc_otg: Microframe scheduler enabled
[ 0.785299] WARN::hcd_init_fiq:459: FIQ on core 1 at 0x8058e63c
[ 0.787601] WARN::hcd_init_fiq:460: FIQ ASM at 0x8058e9ac length 36
[ 0.789921] WARN::hcd_init_fiq:486: MPHI regs_base at 0xb787a000
[ 0.792272] dwc_otg 3f980000.usb: DWC OTG Controller
[ 0.794587] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[ 0.796961] dwc_otg 3f980000.usb: irq 62, io mem 0x00000000
[ 0.799278] Init: Port Power? op_state=1
[ 0.801527] Init: Power Port (0)
[ 0.803904] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[ 0.806212] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 0.808530] usb usb1: Product: DWC OTG Controller
[ 0.810778] usb usb1: Manufacturer: Linux 4.9.28-v7+ dwc_otg_hcd
[ 0.813048] usb usb1: SerialNumber: 3f980000.usb
[ 0.816127] hub 1-0:1.0: USB hub found
[ 0.818347] hub 1-0:1.0: 1 port detected
[ 0.821074] dwc_otg: FIQ enabled
[ 0.821079] dwc_otg: NAK holdoff enabled
[ 0.821084] dwc_otg: FIQ split-transaction FSM enabled
[ 0.821098] Module dwc_common_port init
[ 0.821331] usbcore: registered new interface driver usb-storage
[ 0.823678] mousedev: PS/2 mouse device common for all mice
[ 0.826822] bcm2835-wdt 3f100000.watchdog: Broadcom BCM2835 watchdog timer
[ 0.829369] bcm2835-cpufreq: min=600000 max=1200000
[ 0.832006] sdhci: Secure Digital Host Controller Interface driver
[ 0.834320] sdhci: Copyright(c) Pierre Ossman
[ 0.836842] sdhost-bcm2835 3f202000.sdhost: could not get clk, deferring probe
[ 0.841425] mmc-bcm2835 3f300000.mmc: could not get clk, deferring probe
[ 0.843970] sdhci-pltfm: SDHCI platform and OF driver helper
[ 0.853692] ledtrig-cpu: registered to indicate activity on CPUs
[ 0.856339] hidraw: raw HID events driver (C) Jiri Kosina
[ 0.859006] usbcore: registered new interface driver usbhid
[ 0.861469] usbhid: USB HID core driver
[ 0.864723] vchiq: vchiq_init_state: slot_zero = 0xb6980000, is_master = 0
[ 0.868981] Initializing XFRM netlink socket
[ 0.871519] NET: Registered protocol family 17
[ 0.874110] Key type dns_resolver registered
[ 0.876963] Registering SWP/SWPB emulation handler
[ 0.880139] registered taskstats version 1
[ 0.882918] vc-sm: Videocore shared memory driver
[ 0.885429] [vc_sm_connected_init]: start
[ 0.888364] [vc_sm_connected_init]: end - returning 0
[ 0.896724] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 87, base_baud = 0) is a PL011 rev2
[ 0.903237] sdhost: log_buf @ b6907000 (f6907000)
[ 0.976957] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[ 0.981612] mmc-bcm2835 3f300000.mmc: mmc_debug:0 mmc_debug2:0
[ 0.984051] mmc-bcm2835 3f300000.mmc: DMA channel allocated
[ 1.037020] Indeed it is in host mode hprt0 = 00021501
[ 1.099439] of_cfs_init
[ 1.101745] of_cfs_init: OK
[ 1.104350] Waiting for root device PARTUUID=538ad6ae-02...
[ 1.116363] mmc0: host does not support reading read-only switch, assuming write-enable
[ 1.122820] mmc0: new high speed SDHC card at address 1234
[ 1.125789] mmcblk0: mmc0:1234 SA16G 14.4 GiB
[ 1.127118] random: fast init done
[ 1.132589] mmcblk0: p1 p2
[ 1.138840] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[ 1.142670] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 1.146428] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 1.151381] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[ 1.236664] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[ 1.240883] usb 1-1: new high-speed USB device number 2 using dwc_otg
[ 1.243142] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[ 1.245381] Indeed it is in host mode hprt0 = 00001101
[ 1.257569] devtmpfs: mounted
[ 1.309334] Freeing unused kernel memory: 1024K (80b00000 - 80c00000)
[ 1.320612] mmc1: new high speed SDIO card at address 0001
[ 1.477268] usb 1-1: New USB device found, idVendor=0424, idProduct=9514
[ 1.479744] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 1.483028] hub 1-1:1.0: USB hub found
[ 1.485483] hub 1-1:1.0: 5 ports detected
[ 1.610272] systemd[1]: systemd 215 running in system mode. (+PAM +AUDIT +SELINUX +IMA +SYSVINIT +LIBCRYPTSETUP +GCRYPT +ACL +XZ -SECCOMP -APPARMOR)
[ 1.615348] systemd[1]: Detected architecture 'arm'.
[ 1.733148] NET: Registered protocol family 10
[ 1.737220] systemd[1]: Inserted module 'ipv6'
[ 1.742055] systemd[1]: Set hostname to <mulePi>.
[ 1.744854] systemd[1]: Initializing machine ID from random generator.
[ 1.747697] systemd[1]: Installed transient /etc/machine-id file.
[ 1.807025] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[ 1.937291] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
[ 1.939833] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 1.945243] smsc95xx v1.0.5
[ 2.050815] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:79:6f:08
[ 2.104972] systemd[1]: Cannot add dependency job for unit regenerate_ssh_host_keys.service, ignoring: Unit regenerate_ssh_host_keys.service failed to load: No such file or directory.
[ 2.113618] systemd[1]: Cannot add dependency job for unit display-manager.service, ignoring: Unit display-manager.service failed to load: No such file or directory.
[ 2.125148] systemd[1]: Starting Forward Password Requests to Wall Directory Watch.
[ 2.131276] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[ 2.146999] usb 1-1.4: new full-speed USB device number 4 using dwc_otg
[ 2.303730] usb 1-1.4: New USB device found, idVendor=23c1, idProduct=b015
[ 2.305791] usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=220
[ 2.309993] usb 1-1.4: Product: The Replicator
[ 2.312145] usb 1-1.4: Manufacturer: MakerBot Industries
[ 2.314359] usb 1-1.4: SerialNumber: 75237333536351511290
[ 2.561137] systemd-udevd[139]: starting version 215
[ 2.781394] cdc_acm 1-1.4:1.0: ttyACM0: USB ACM device
[ 2.782370] usbcore: registered new interface driver cdc_acm
[ 2.782385] cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters
[ 2.848274] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[ 3.114332] usbcore: registered new interface driver brcmfmac
[ 3.280640] brcmfmac: Firmware version = wl0: May 27 2016 00:13:38 version 7.45.41.26 (r640327) FWID 01-df77e4a7
[ 3.302948] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[ 3.687637] systemd-journald[143]: Received request to flush runtime journal from PID 1
[ 4.291592] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[ 4.291624] brcmfmac: power management disabled
[ 4.603294] uart-pl011 3f201000.serial: no DMA platform data
[ 4.653906] Adding 102396k swap on /var/swap. Priority:-1 extents:2 across:118780k SSFS
[ 5.239353] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[ 5.239636] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 6.552267] random: crng init done
[ 6.977687] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[ 6.979513] smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0x45E1
[ 10.512222] Bluetooth: Core ver 2.22
[ 10.512292] NET: Registered protocol family 31
[ 10.512297] Bluetooth: HCI device and connection manager initialized
[ 10.512316] Bluetooth: HCI socket layer initialized
[ 10.512330] Bluetooth: L2CAP socket layer initialized
[ 10.512364] Bluetooth: SCO socket layer initialized
[ 10.525067] Bluetooth: HCI UART driver ver 2.3
[ 10.525081] Bluetooth: HCI UART protocol H4 registered
[ 10.525086] Bluetooth: HCI UART protocol Three-wire (H5) registered
[ 10.525271] Bluetooth: HCI UART protocol Broadcom registered
[ 10.704468] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[ 10.704476] Bluetooth: BNEP filters: protocol multicast
[ 10.704490] Bluetooth: BNEP socket layer initialized
[ 12.353100] ip_tables: (C) 2000-2006 Netfilter Core Team
output of pi@mulePi:/var/log $ cat syslog
Feb 22 07:17:01 mulePi CRON[31714]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 22 08:17:02 mulePi CRON[6594]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 22 09:17:01 mulePi CRON[13755]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 22 10:17:01 mulePi CRON[21261]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 22 11:17:01 mulePi CRON[28219]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 22 12:17:01 mulePi CRON[4027]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 22 13:17:01 mulePi CRON[12022]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 22 14:17:01 mulePi CRON[20035]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 22 15:17:01 mulePi CRON[28057]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 22 16:17:01 mulePi CRON[3829]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 22 17:17:01 mulePi CRON[11009]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 22 18:17:01 mulePi CRON[19075]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 22 19:17:01 mulePi CRON[26996]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 22 20:17:01 mulePi CRON[2805]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 22 21:17:01 mulePi CRON[10828]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 22 22:17:01 mulePi CRON[18814]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 22 23:17:01 mulePi CRON[26630]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 23 00:17:01 mulePi CRON[31444]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 23 01:00:20 mulePi systemd[1]: Starting Cleanup of Temporary Directories...
Feb 23 01:00:20 mulePi systemd[1]: Started Cleanup of Temporary Directories.
Feb 23 01:17:01 mulePi CRON[31489]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 23 02:17:01 mulePi CRON[31517]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 23 03:17:01 mulePi CRON[31545]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
At this point I have restarted the octoprint service and gone back to printing.
Hoping the logs have something this time.
Also there shouldn't be any reason why the pi loses connectivity to the internet. The office didn't seem to lose internet, plus the router's logged device up time for both the WIFI connection and the ethernet connection on the pi doesn't seem to indicate a loss of connectivity.
Please help!
stidf
on 23 Feb 2018
Your logs are incomplete since you used cat and just copy-pasted the contents of your terminal, which means anything to the right of the width of your window got cut off. What is there though doesn't hint at anything at all other than it still being offline. Same goes for your dmesg and syslog. Did you reboot the Pi in between? Because that would make dmesg sadly pretty unhelpful.
What I see is that it's still offline (or at least "OctoPrint Anywhere" keeps complaining about that). I can't tell you why it's offline. But just because the network you are in in principle has a internet connection doesn't mean your Pi does. If its default gateway or nameserver isn't set correctly, you can count on it being offline. Or if your office's firewall blocks it.
In any case, this sounds more and more like an issue with your environment rather than anything else, so the bug tracker isn't actually the right location for this. I suggest you try the screen approach I suggested in this comment and the next time it happens provide the output of that plus /var/log/syslog and for good measure also /var/log/syslog.1. And please don't provide that stuff by cating and copy-paste, use an SCP client to get the actual log files off the Pi (e.g. WinSCP if you are on Windows) and provide them. It doesn't look like whatever causes the crash also causes a log entry to be written, so the only chance to get information on that is to actually capture everything on stdout while running from console. My money would be on some kind of segfault.
foosel
on 23 Feb 2018
Good thing I didn't reboot! Getting stronger with my terminal-fu.
pi@mulePi:/var/log $ uptime
03:03:26 up 6 days, 2:20, 1 user, load average: 0.17, 0.27, 0.31
pi@mulePi:/var/log $
octoprint.current.log
octoprint.log.2018-02-21.log
octoprint.log.2018-02-22.log
octoprint.log.2018-02-18.log
octoprint.log.2018-02-19.log
octoprint.log.2018-02-20.log
dmesg.log
messages.log
syslog.log
Edit: initially uploaded the incorrect octoprint log files.
stidf
on 24 Feb 2018
Got the screen logging business all setup, so the next crash should be caught by the terminal.
stidf
on 24 Feb 2018
Output from screen when I got another crash. It ends with a segmentation fault.
```
Starting the server via "octoprint" is deprecated, please use "octoprint serve" from now on.
2018-03-01 03:04:46,852 - octoprint.startup - INFO - *************************
2018-03-01 03:04:46,853 - octoprint.startup - INFO - Starting OctoPrint 1.3.6
2018-03-01 03:04:46,853 - octoprint.startup - INFO - *************************
2018-03-01 03:04:46,897 - octoprint.util.connectivity_checker - INFO - Connectivity changed from offline to online
2018-03-01 03:04:47,740 - octoprint.startup - INFO - Blacklist processing done
2018-03-01 03:04:47,818 - octoprint.plugin.core - INFO - Loading plugins from /home/pi/oprint/lib/python2.7/site-packages/OctoPrint-1.3.6-py2.7.egg/octoprint/plugins, /
home/pi/.octoprint/plugins and installed plugin packages...
2018-03-01 03:04:49,284 - octoprint.plugin.core - INFO - Found 11 plugin(s) providing 11 mixin implementations, 12 hook handlers
2018-03-01 03:04:49,407 - octoprint.server - INFO - Intermediary server started
2018-03-01 03:04:49,408 - octoprint.plugin.core - INFO - Loading plugins from /home/pi/oprint/lib/python2.7/site-packages/OctoPrint-1.3.6-py2.7.egg/octoprint/plugins, /
home/pi/.octoprint/plugins and installed plugin packages...
2018-03-01 03:04:49,696 - octoprint.plugin.core - INFO - Found 11 plugin(s) providing 11 mixin implementations, 12 hook handlers
2018-03-01 03:04:49,727 - octoprint.filemanager.storage - INFO - Initializing the file metadata for /home/pi/.octoprint/uploads...
2018-03-01 03:04:50,794 - octoprint.filemanager.storage - INFO - ... file metadata for /home/pi/.octoprint/uploads initialized successfully.
2018-03-01 03:04:50,897 - octoprint.plugins.softwareupdate - INFO - Loaded version cache from disk
2018-03-01 03:04:53,282 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python -m pip" as command to invoke pip
2018-03-01 03:04:55,620 - octoprint.util.pip - INFO - Version of pip is 9.0.1
2018-03-01 03:04:55,623 - octoprint.plugin.core - INFO - Initialized 11 plugin implementation(s)
2018-03-01 03:04:55,631 - octoprint.plugin.core - INFO - 11 plugin(s) registered with the system:
| Announcement Plugin (bundled) = /home/pi/oprint/lib/python2.7/site-packages/OctoPrint-1.3.6-py2.7.egg/octoprint/plugins/announcements
| Core Wizard (bundled) = /home/pi/oprint/lib/python2.7/site-packages/OctoPrint-1.3.6-py2.7.egg/octoprint/plugins/corewizard
| CuraEngine (<= 15.04) (bundled) = /home/pi/oprint/lib/python2.7/site-packages/OctoPrint-1.3.6-py2.7.egg/octoprint/plugins/cura
| Discovery (bundled) = /home/pi/oprint/lib/python2.7/site-packages/OctoPrint-1.3.6-py2.7.egg/octoprint/plugins/discovery
| GPX (2.6.0) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_GPX
| OctoPi Support Plugin (bundled) = /home/pi/oprint/lib/python2.7/site-packages/OctoPrint-1.3.6-py2.7.egg/octoprint/plugins/octopi_support
| OctoPrint Anywhere (0.6.0) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_anywhere
| Plugin Manager (bundled) = /home/pi/oprint/lib/python2.7/site-packages/OctoPrint-1.3.6-py2.7.egg/octoprint/plugins/pluginmanager
| Print History Plugin (1.2) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_printhistory
| Software Update (bundled) = /home/pi/oprint/lib/python2.7/site-packages/OctoPrint-1.3.6-py2.7.egg/octoprint/plugins/softwareupdate
| Virtual Printer (bundled) = /home/pi/oprint/lib/python2.7/site-packages/OctoPrint-1.3.6-py2.7.egg/octoprint/plugins/virtual_printer
2018-03-01 03:04:57,213 - octoprint.environment - INFO - Detected environment is Python 2.7.9 under Linux (linux2). Details:
| hardware:
| cores: 4
| freq: 1200.0
| ram: 901689344
| os:
| id: linux
| platform: linux2
| plugins:
| octopi_support:
| model: 3B
| revision: a22082
| version: 0.14.0
| python:
| pip: 9.0.1
| version: 2.7.9
| virtualenv: /home/pi/oprint
2018-03-01 03:04:57,222 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/webassets...
2018-03-01 03:04:57,246 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/.webassets-cache...
2018-03-01 03:04:57,517 - octoprint.server - INFO - Shutting down intermediary server...
2018-03-01 03:04:57,544 - octoprint.server - INFO - Intermediary server shut down
2018-03-01 03:04:57,546 - octoprint.events - INFO - Processing startup event, this is our first event
2018-03-01 03:04:57,547 - octoprint.events - INFO - Adding 1 events to queue that were held back before startup event
2018-03-01 03:04:57,575 - octoprint.filemanager - INFO - Adding backlog items from all storage types to analysis queue...
2018-03-01 03:04:57,650 - octoprint.filemanager - INFO - Added 0 items from storage type "local" to analysis queue
2018-03-01 03:04:57,651 - octoprint.plugins.pluginmanager - INFO - Loaded plugin repository data from disk, was still valid
2018-03-01 03:04:57,711 - octoprint.plugins.pluginmanager - INFO - Loaded notice data from disk, was still valid
2018-03-01 03:04:58,089 - octoprint.plugins.GPX - INFO - Connecting through x3g.
2018-03-01 03:04:58,090 - octoprint.plugins.GPX - INFO - GPXPrinter created, port: /dev/ttyACM0, baudrate: 115200
2018-03-01 03:05:00,127 - octoprint.plugins.discovery - INFO - Registered OctoPrint instance "MulePi" for _http._tcp
2018-03-01 03:05:00,147 - octoprint.plugins.discovery - INFO - Registered OctoPrint instance "MulePi" for _octoprint._tcp
2018-03-01 03:05:00,153 - octoprint.plugins.discovery - INFO - Registered OctoPrint instance "MulePi" for SSDP
2018-03-01 03:05:00,155 - octoprint.server - INFO - Listening on http://0.0.0.0:5000
2018-03-01 03:05:00,325 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 03:05:00,458 - octoprint.server.util.sockjs - INFO - New connection from client: 127.0.0.1
2018-03-01 03:05:00,529 - octoprint.plugins.pluginmanager - INFO - Loaded plugin repository data from disk, was still valid
2018-03-01 03:05:00,576 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 03:05:00,836 - octoprint.server.preemptive_cache - INFO - Preemptively caching / (ui _default) for {'query_string': 'l10n=en', 'path': '/', 'base_url': 'http
://mulepi/'}
2018-03-01 03:05:00,843 - octoprint.plugins.pluginmanager - INFO - Loaded notice data from disk, was still valid
2018-03-01 03:05:01,550 - octoprint.server.util.sockjs - INFO - New connection from client: 192.168.2.196
2018-03-01 03:05:02,121 - octoprint.plugins.GPX - INFO - gpx.connect succeeded
2018-03-01 03:05:02,128 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2018-03-01 03:05:02,164 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2018-03-01 03:05:04,215 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2018-03-01 03:05:04,248 - octoprint.util.comm - INFO - Printer reports firmware name "Sailfish"
2018-03-01 03:05:12,193 - octoprint.server.preemptive_cache - INFO - ... done in 11.38s
2018-03-01 03:05:12,194 - octoprint.server.preemptive_cache - INFO - Preemptively caching / (ui _default) for {'query_string': 'l10n=en', 'path': '/', 'base_url': 'http
://octopi/'}
2018-03-01 03:05:16,416 - octoprint.server.preemptive_cache - INFO - ... done in 4.22s
2018-03-01 03:05:16,418 - octoprint.server.preemptive_cache - INFO - Preemptively caching / (ui _default) for {'query_string': 'l10n=en', 'path': '/', 'base_url': 'http
://localhost:12345/'}
2018-03-01 03:05:20,603 - octoprint.server.preemptive_cache - INFO - ... done in 4.19s
2018-03-01 03:10:18,168 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2018-03-01 03:10:21,809 - octoprint.server.util.sockjs - INFO - Client connection closed: 192.168.2.196
2018-03-01 06:03:32,867 - backoff - ERROR - Backing off __forward_ws__(...) for 0.3s (error: [Errno 14] Bad address)
[SSL: SSLV3_ALERT_BAD_RECORD_MAC] sslv3 alert bad record mac (_ssl.c:1750)
closed
2018-03-01 06:03:33,978 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 06:03:33,984 - backoff - ERROR - Backing off __forward_ws__(...) for 0.5s (error: [Errno 14] Bad address)
2018-03-01 06:03:34,746 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 06:03:34,758 - backoff - ERROR - Backing off __forward_ws__(...) for 0.7s (error: [Errno 14] Bad address)
2018-03-01 06:03:35,947 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 06:03:35,963 - backoff - ERROR - Backing off __forward_ws__(...) for 1.8s (error: [Errno 14] Bad address)
2018-03-01 06:03:37,881 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 06:03:37,899 - backoff - ERROR - Backing off __forward_ws__(...) for 2.7s (error: [Errno 14] Bad address)
2018-03-01 06:03:40,715 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 06:03:40,717 - backoff - ERROR - Backing off __forward_ws__(...) for 0.0s (error: [Errno 14] Bad address)
2018-03-01 06:03:40,872 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 06:03:40,874 - backoff - ERROR - Backing off __forward_ws__(...) for 5.0s (error: [Errno 14] Bad address)
2018-03-01 06:03:45,933 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 06:03:45,935 - backoff - ERROR - Backing off __forward_ws__(...) for 5.9s (error: [Errno 14] Bad address)
2018-03-01 06:03:51,865 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 06:03:51,868 - backoff - ERROR - Giving up __forward_ws__(...) after 8 tries (error: [Errno 14] Bad address)
2018-03-01 06:03:51,881 - anywhere - WARNING - Reached max backoff in waiting for server ws connection
2018-03-01 06:03:52,673 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 06:03:53,310 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 06:03:53,796 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 06:03:54,110 - anywhere - WARNING - Not connected to server ws or connection lost
[SSL: BAD_WRITE_RETRY] bad write retry (_ssl.c:1625)
2018-03-01 06:40:22,879 - anywhere - WARNING - Not connected to server ws or connection lost
closed
2018-03-01 06:40:23,953 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 06:40:28,259 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 06:40:40,684 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 06:40:40,685 - backoff - ERROR - Giving up __forward_ws__(...) after 8 tries (None)
2018-03-01 06:40:40,695 - anywhere - WARNING - Reached max backoff in waiting for server ws connection
2018-03-01 06:40:41,808 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 06:40:42,249 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 07:01:25,257 - backoff - ERROR - Backing off stream_up(...) for 0.8s (ConnectionError: [Errno 104] Connection reset by peer)
2018-03-01 13:42:19,930 - backoff - ERROR - Backing off __forward_ws__(...) for 0.3s (error: [Errno 14] Bad address)
[Errno 104] Connection reset by peer
closed
2018-03-01 13:42:20,482 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 13:42:20,489 - backoff - ERROR - Backing off __forward_ws__(...) for 0.3s (error: [Errno 14] Bad address)
2018-03-01 13:42:20,851 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 13:42:21,153 - backoff - ERROR - Backing off __forward_ws__(...) for 0.9s (error: [Errno 14] Bad address)
2018-03-01 13:42:22,113 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 13:42:22,115 - backoff - ERROR - Backing off __forward_ws__(...) for 0.3s (error: [Errno 14] Bad address)
2018-03-01 13:42:22,571 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 13:42:22,576 - backoff - ERROR - Backing off __forward_ws__(...) for 2.1s (error: [Errno 14] Bad address)
2018-03-01 13:42:24,667 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 13:42:24,672 - backoff - ERROR - Backing off __forward_ws__(...) for 4.3s (error: [Errno 14] Bad address)
2018-03-01 13:42:29,737 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 13:42:29,739 - backoff - ERROR - Backing off __forward_ws__(...) for 6.4s (error: [Errno 14] Bad address)
2018-03-01 13:42:36,727 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 13:42:36,731 - backoff - ERROR - Backing off __forward_ws__(...) for 0.4s (error: [Errno 14] Bad address)
2018-03-01 13:42:37,107 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 13:42:37,110 - backoff - ERROR - Giving up __forward_ws__(...) after 8 tries (error: [Errno 14] Bad address)
2018-03-01 13:42:37,125 - anywhere - WARNING - Reached max backoff in waiting for server ws connection
2018-03-01 13:42:40,623 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 13:42:40,816 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 13:42:41,503 - anywhere - WARNING - Not connected to server ws or connection lost
[SSL: BAD_WRITE_RETRY] bad write retry (_ssl.c:1625)
2018-03-01 15:20:18,349 - anywhere - WARNING - Not connected to server ws or connection lost
closed
2018-03-01 15:20:18,491 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 15:20:23,119 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 15:20:27,751 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 15:20:35,594 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 15:20:35,596 - backoff - ERROR - Giving up __forward_ws__(...) after 8 tries (None)
2018-03-01 15:20:35,599 - anywhere - WARNING - Reached max backoff in waiting for server ws connection
2018-03-01 15:20:40,926 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 15:20:41,407 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 15:20:41,420 - anywhere - WARNING - Not connected to server ws or connection lost
[SSL: SSLV3_ALERT_BAD_RECORD_MAC] sslv3 alert bad record mac (_ssl.c:1750)
closed
2018-03-01 16:10:55,602 - backoff - ERROR - Backing off __forward_ws__(...) for 0.0s (WebSocketConnectionClosedException: socket is already closed.)
2018-03-01 16:10:55,614 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:10:55,616 - backoff - ERROR - Backing off __forward_ws__(...) for 0.4s (WebSocketConnectionClosedException: socket is already closed.)
2018-03-01 16:10:56,052 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:10:56,058 - backoff - ERROR - Backing off __forward_ws__(...) for 0.2s (WebSocketConnectionClosedException: socket is already closed.)
2018-03-01 16:10:56,351 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:10:56,355 - backoff - ERROR - Backing off __forward_ws__(...) for 1.1s (WebSocketConnectionClosedException: socket is already closed.)
2018-03-01 16:10:57,479 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:10:57,482 - backoff - ERROR - Backing off __forward_ws__(...) for 2.6s (WebSocketConnectionClosedException: socket is already closed.)
2018-03-01 16:11:00,160 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:11:00,162 - backoff - ERROR - Backing off __forward_ws__(...) for 1.0s (WebSocketConnectionClosedException: socket is already closed.)
2018-03-01 16:11:01,197 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:11:01,208 - backoff - ERROR - Backing off __forward_ws__(...) for 5.2s (WebSocketConnectionClosedException: socket is already closed.)
2018-03-01 16:11:06,505 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:11:06,508 - backoff - ERROR - Backing off __forward_ws__(...) for 7.0s (WebSocketConnectionClosedException: socket is already closed.)
2018-03-01 16:11:13,594 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:11:13,597 - backoff - ERROR - Giving up __forward_ws__(...) after 8 tries (WebSocketConnectionClosedException: socket is already closed.)
2018-03-01 16:11:13,601 - anywhere - WARNING - Reached max backoff in waiting for server ws connection
2018-03-01 16:11:17,259 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:11:17,288 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:11:17,850 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:23:12,208 - backoff - ERROR - Backing off __forward_ws__(...) for 0.0s (error: [Errno 14] Bad address)
[Errno 32] Broken pipe
closed
2018-03-01 16:23:16,392 - backoff - ERROR - Backing off __forward_ws__(...) for 0.1s (WebSocketConnectionClosedException: Connection is already closed.)
2018-03-01 16:23:16,539 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:23:16,545 - backoff - ERROR - Backing off __forward_ws__(...) for 0.3s (WebSocketConnectionClosedException: Connection is already closed.)
2018-03-01 16:23:16,825 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:23:16,828 - backoff - ERROR - Backing off __forward_ws__(...) for 0.5s (WebSocketConnectionClosedException: Connection is already closed.)
2018-03-01 16:23:17,414 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:23:17,419 - backoff - ERROR - Backing off __forward_ws__(...) for 0.6s (WebSocketConnectionClosedException: Connection is already closed.)
2018-03-01 16:23:18,018 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:23:18,020 - backoff - ERROR - Backing off __forward_ws__(...) for 1.6s (WebSocketConnectionClosedException: Connection is already closed.)
2018-03-01 16:23:19,758 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:23:19,776 - backoff - ERROR - Backing off __forward_ws__(...) for 2.9s (WebSocketConnectionClosedException: Connection is already closed.)
2018-03-01 16:23:22,928 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:23:22,940 - backoff - ERROR - Backing off __forward_ws__(...) for 1.0s (WebSocketConnectionClosedException: Connection is already closed.)
2018-03-01 16:23:23,972 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:23:23,974 - backoff - ERROR - Backing off __forward_ws__(...) for 11.4s (WebSocketConnectionClosedException: Connection is already closed.)
2018-03-01 16:23:35,431 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:23:35,576 - backoff - ERROR - Giving up __forward_ws__(...) after 8 tries (WebSocketConnectionClosedException: Connection is already closed.)
2018-03-01 16:23:35,581 - anywhere - WARNING - Reached max backoff in waiting for server ws connection
2018-03-01 16:24:03,204 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:24:03,354 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:24:03,559 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:24:04,107 - anywhere - WARNING - Not connected to server ws or connection lost
[Errno 0] Error
closed
2018-03-01 16:31:29,259 - backoff - ERROR - Backing off __forward_ws__(...) for 0.9s (error: [Errno 32] Broken pipe)
2018-03-01 16:31:30,231 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:31:30,232 - backoff - ERROR - Backing off __forward_ws__(...) for 0.3s (error: [Errno 32] Broken pipe)
2018-03-01 16:31:30,567 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:31:30,569 - backoff - ERROR - Backing off __forward_ws__(...) for 1.0s (error: [Errno 32] Broken pipe)
2018-03-01 16:31:31,873 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:31:31,879 - backoff - ERROR - Backing off __forward_ws__(...) for 1.7s (error: [Errno 32] Broken pipe)
2018-03-01 16:31:33,630 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:31:33,639 - backoff - ERROR - Backing off __forward_ws__(...) for 1.1s (error: [Errno 32] Broken pipe)
2018-03-01 16:31:34,807 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:31:34,830 - backoff - ERROR - Backing off __forward_ws__(...) for 1.3s (error: [Errno 32] Broken pipe)
2018-03-01 16:31:36,125 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:31:36,127 - backoff - ERROR - Backing off __forward_ws__(...) for 7.4s (error: [Errno 32] Broken pipe)
2018-03-01 16:31:43,630 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:31:43,633 - backoff - ERROR - Backing off __forward_ws__(...) for 11.9s (error: [Errno 32] Broken pipe)
2018-03-01 16:31:55,609 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:31:55,611 - backoff - ERROR - Giving up __forward_ws__(...) after 8 tries (error: [Errno 32] Broken pipe)
2018-03-01 16:31:55,629 - anywhere - WARNING - Reached max backoff in waiting for server ws connection
2018-03-01 16:32:40,514 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:32:41,462 - anywhere - WARNING - Not connected to server ws or connection lost
[SSL: BAD_WRITE_RETRY] bad write retry (_ssl.c:1625)
2018-03-01 16:42:45,387 - anywhere - WARNING - Not connected to server ws or connection lost
closed
2018-03-01 16:42:46,657 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:42:48,005 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:42:52,769 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:43:00,006 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:43:07,628 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:43:07,637 - backoff - ERROR - Giving up __forward_ws__(...) after 8 tries (None)
2018-03-01 16:43:07,639 - anywhere - WARNING - Reached max backoff in waiting for server ws connection
2018-03-01 16:44:58,006 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:44:58,670 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:44:59,134 - anywhere - WARNING - Not connected to server ws or connection lost
[SSL: BAD_WRITE_RETRY] bad write retry (_ssl.c:1625)
2018-03-01 16:50:31,971 - anywhere - WARNING - Not connected to server ws or connection lost
closed
2018-03-01 16:50:33,044 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:50:37,526 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:50:43,875 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:50:53,484 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:50:53,490 - backoff - ERROR - Giving up __forward_ws__(...) after 8 tries (None)
2018-03-01 16:50:53,503 - anywhere - WARNING - Reached max backoff in waiting for server ws connection
2018-03-01 16:51:19,012 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:51:19,592 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 16:51:19,922 - anywhere - WARNING - Not connected to server ws or connection lost
[SSL: SSLV3_ALERT_BAD_RECORD_MAC] sslv3 alert bad record mac (_ssl.c:1750)
closed
2018-03-01 17:07:23,052 - backoff - ERROR - Backing off __forward_ws__(...) for 0.1s (WebSocketConnectionClosedException: Connection is already closed.)
2018-03-01 17:07:23,137 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 17:07:23,147 - backoff - ERROR - Backing off __forward_ws__(...) for 0.6s (WebSocketConnectionClosedException: Connection is already closed.)
2018-03-01 17:07:23,778 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 17:07:23,780 - backoff - ERROR - Backing off __forward_ws__(...) for 0.1s (WebSocketConnectionClosedException: Connection is already closed.)
2018-03-01 17:07:23,908 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 17:07:23,910 - backoff - ERROR - Backing off __forward_ws__(...) for 1.9s (WebSocketConnectionClosedException: Connection is already closed.)
2018-03-01 17:07:26,039 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 17:07:26,041 - backoff - ERROR - Backing off __forward_ws__(...) for 0.6s (WebSocketConnectionClosedException: Connection is already closed.)
2018-03-01 17:07:26,792 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 17:07:26,794 - backoff - ERROR - Backing off __forward_ws__(...) for 1.0s (WebSocketConnectionClosedException: Connection is already closed.)
2018-03-01 17:07:27,968 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 17:07:27,984 - backoff - ERROR - Backing off __forward_ws__(...) for 3.5s (WebSocketConnectionClosedException: Connection is already closed.)
2018-03-01 17:07:31,648 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 17:07:31,651 - backoff - ERROR - Backing off __forward_ws__(...) for 3.2s (WebSocketConnectionClosedException: Connection is already closed.)
2018-03-01 17:07:34,909 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 17:07:34,910 - backoff - ERROR - Giving up __forward_ws__(...) after 8 tries (WebSocketConnectionClosedException: Connection is already closed.)
2018-03-01 17:07:34,914 - anywhere - WARNING - Reached max backoff in waiting for server ws connection
2018-03-01 17:10:12,050 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 17:10:12,828 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 17:10:13,465 - anywhere - WARNING - Not connected to server ws or connection lost
2018-03-01 17:10:13,470 - anywhere - WARNING - Not connected to server ws or connection lost
Segmentation fault
stidf
on 2 Mar 2018
This is what I feared. So the python process is just crashing away. This could have multiple reasons, one of which being unlimited recursion (others being faulty RAM or bugs in C modules - note that OctoPrint itself doesn't have any C modules but depends on libraries that DO have them).
It might be worth testing on another RPi if you have one on hand, especially since you stated that your webcam server on the same device also crashes. It might be faulty RAM causing this.
If this is not it, you should rule out any of your plugins causing this. Considering that your printer depends on the GPX module to work if I understood correctly, I understand that running productively in safe mode is out of the question, but I would like to ask you to disable all other third party plugins that you have installed (based on your log up there that should only be OctoPrint Anywhere and Print History) and then see if you can still reproduce the issue.
@markwal the GPX plugin does have a native C extension, right? Are you aware of any issues like this?
Your's is the only case of such a segfault that I'm currently aware, so for now I'm more leaning towards faulty RAM or a plugin being at fault here than some crazy difficult to trigger segfault condition caused by OctoPrint itself.
foosel
on 2 Mar 2018
I am currently experiencing the exact same issues so it may not be a hardware related problem.
kisersosay
on 12 Mar 2018
@kisersosay to quote the contribution guidelines:
Always use the following template (please remove what's within [...], that's only provided here as some additional information for you), even if only adding a "me too" to an existing ticket
Also include the output of the screen test as mentioned above.
foosel
on 12 Mar 2018
And, by the way, yes GPX is largely C code compiled to native and can cause a segfault though I haven't seen one myself in quite some time.
markwal
on 12 Mar 2018
@stidf any updates here with regards to testing with all plugins but GPX disabled, on another Pi and such?
foosel
on 27 Mar 2018
Unfortunately no. Printer doesn't function without the GPX plugin and I just haven't had the time to do the hardware swap yet.
stidf
on 28 Mar 2018
So a couple of updates: I got a new raspberryPi to run the print server and have since updated both the octoprint and GPX plugins. The failure rate seems to have gone down, but I am still getting the same segment fault crashes.
stidf
on 15 May 2018
Are you also using a new micro SD card? And/or fresh image? FWIW I haven't seen a seg fault in quite some time.
markwal
on 15 May 2018
The only new hardware was a new raspberry pi. I moved the SD card from the old pi to the new pi and kept running with the same image. I haven't changed the mirco SD card out yet, but I have reflashed the image in an earlier attempt at troubleshooting.
The I applied the new updates for both Octoprint and the GPX plugin when they were recently published. I ran crash free for most of the month of April then had 3 crashes in the past week. Hence me reopening the ticket.
stidf
on 15 May 2018
Did you try running this only with stock OctoPrint and the GPX plugin, so without any further 3rd party plugins, as I suggested earlier? I just want to rule out that we are barking up the wrong tree here looking at the OctoPrint/GPX combo.
foosel
on 16 May 2018
Yes, prior to submitting the bug report. in 2017, I disabled all plugins
but the GPX plugin and ran for about 3 weeks before I had a similar crash,
after which I turn everything back on. I have not tried to it again
recently.
stidf
on 16 May 2018
So, I can't reproduce this, my instances are all rock solid since months. However, #2647 shows similar symptoms (still waiting for the screen test results) and also had the OctoPrint Anywhere plugin installed. Might be coincidence, might not be, but it's an interesting data point nonetheless.
foosel
on 22 May 2018
At this point I am going to try a new SD card and new image on the new pi. Only install Octoprint and the GPX plugin. Then get the web cam running and get printing. Then see what happens.
As for #2647, I believe that we are experiencing the same issue. I don't understand why the printer doesn't cancel the print after it loses the serial connection. I am assuming that the printer is just waiting for more serial commands that the pi is no longer giving because of the seg fault. Hence the printer just "hanging" with the exturder hot and the build plate hot. I would assume that at some point the printer would cancel the print after missing the serial talkback with the print server, but this clearly isn't the case.
stidf
on 25 May 2018
I would assume that at some point the printer would cancel the print after missing the serial talkback with the print server, but this clearly isn't the case.
You are expecting way more intelligence and thoughtfulness from that printer controller than they have. Your printer doesn't even know there's a print job going on (because pretty much all firmware doesn't have any kind of command to indicate that being the case), all it sees is commands from serial which it executes and then waits for more. Some printers have some kind of timeout (no new commands within in a certain timeframe = shut off heaters), but most don't.
There's no well defined protocol, there's no consistency. That all this works at all surprises me all the time to be honest (and takes a ton of workarounds)
foosel
on 25 May 2018
New at Octoprint. First long print. Crashed mid-print. Don't think this beta garbage is worth it.
Never had an SD card crash in years!
LDHall77
on 22 Jan 2019
Related issues
foosel
路
4Comments
halxinate
路
4Comments
JohnOCFII
路
5Comments
halkeye
路
4Comments
dkingsjr
路
5Comments