nanoDLP

adam

Member

Registered: 2016-02-18

Posts: 100

Printer crashed just shy of finishing an 8h print

In the early morning i came to find a failed print, luckily i could recover most of the pieces

failed at 1232/1585 layers

this is the last content of the LOG (i will post more if needed):

2016/03/16 05:02:33.776256 {"Layer":"-","module":"GCODE","level":"Info","action":"Waiting","msg":"Waiting for Wait GPIO LOW"}
2016/03/16 05:02:46.734658 {"Layer":"1232","module":"Z-Axis","level":"Info","action":"Moving to Layer 1232","msg":"-"}
2016/03/16 05:02:46.966426 {"Layer":"-","module":"Image","level":"Info","action":"Display Frame","msg":"public/plates/114/1232.png"}
2016/03/16 05:02:46.966714 {"Layer":"-","module":"Shutter","level":"Info","action":"Shutter Open","msg":"-"}
2016/03/16 05:02:48.440378 {"Layer":"-","module":"Image","level":"Info","action":"Clear Screen","msg":"-"}
2016/03/16 05:02:48.992826 {"Layer":"-","module":"Camera","level":"Info","action":"Taking Photo","msg":"[],<nil>"}
2016/03/16 05:02:49.606565 {"Layer":"-","module":"Terminal","level":"Info","action":"Data Received","msg":"zd	   2¢d	  
¬)d	   PÀd	   È8d	   dÔd	    pd	   È8d	  ôed	   È8d	   
"}
2016/03/16 05:02:49.733095 {"Layer":"-","module":"GCODE","level":"Info","action":"Waiting","msg":"Waiting for Wait GPIO LOW"}
runtime/cgo: pthread_create failed: Resource temporarily unavailable
SIGABRT: abort
PC=0x76ca18dc m=148

goroutine 0 [idle]:

goroutine 6 [syscall]:
runtime.notetsleepg(0x7572cc, 0xb23f79db, 0x0, 0x1090f401)
	/usr/local/go/src/runtime/lock_futex.go:205 +0x4c fp=0x10918788 sp=0x10918770
runtime.timerproc()
	/usr/local/go/src/runtime/time.go:209 +0x11c fp=0x109187dc sp=0x10918788
runtime.goexit()
	/usr/local/go/src/runtime/asm_arm.s:990 +0x4 fp=0x109187dc sp=0x109187dc
created by runtime.addtimerLocked
	/usr/local/go/src/runtime/time.go:116 +0x1c4

goroutine 1 [IO wait, 85 minutes]:
net.runtime_pollWait(0x75a79408, 0x72, 0x0)
	/usr/local/go/src/runtime/netpoll.go:160 +0x60
net.(*pollDesc).Wait(0x10a50078, 0x72, 0x0, 0x0)
	/usr/local/go/src/net/fd_poll_runtime.go:73 +0x34
net.(*pollDesc).WaitRead(0x10a50078, 0x0, 0x0)
	/usr/local/go/src/net/fd_poll_runtime.go:78 +0x30
net.(*netFD).accept(0x10a50040, 0x0, 0x71144178, 0x10ce6290)
	/usr/local/go/src/net/fd_unix.go:426 +0x21c
net.(*TCPListener).AcceptTCP(0x10a3c778, 0x10947b14, 0x0, 0x0)
	/usr/local/go/src/net/tcpsock_posix.go:254 +0x4c
net/http.tcpKeepAliveListener.Accept(0x10a3c778, 0x0, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/server.go:2427 +0x3c
net/http.(*Server).Serve(0x10a78000, 0x71144158, 0x10a3c778, 0x0, 0x0)
	/usr/local/go/src/net/http/server.go:2117 +0xfc
net/http.(*Server).ListenAndServe(0x10a78000, 0x0, 0x0)
	/usr/local/go/src/net/http/server.go:2098 +0x124
net/http.ListenAndServe(0x10a48444, 0x3, 0x711440d8, 0x109a43f0, 0x0, 0x0)
	/usr/local/go/src/net/http/server.go:2195 +0x90
github.com/plimble/ace.(*Ace).Run(0x109a43f0, 0x10a48444, 0x3)
	/home/pi/go/src/github.com/plimble/ace/ace.go:75 +0x74
main.webInit()
	/home/pi/printer/app/web.go:824 +0x2660
main.main()
	/home/pi/printer/app/server.go:58 +0x110

goroutine 17 [syscall, 429 minutes, locked to thread]:
runtime.goexit()
	/usr/local/go/src/runtime/asm_arm.s:990 +0x4

goroutine 19 [sleep]:
time.Sleep(0x2a05f200, 0x1)
	/usr/local/go/src/runtime/time.go:59 +0x104
main.faultDetection()
	/home/pi/printer/app/hardware-interface.go:244 +0x300
created by main.hwInit
	/home/pi/printer/app/hardware-interface.go:27 +0x60

goroutine 927 [sleep]:
time.Sleep(0xb2d05e00, 0x0)
	/usr/local/go/src/runtime/time.go:59 +0x104
main.gcodeExecute(0x10be0f73, 0x0)
	/home/pi/printer/app/gcode.go:46 +0x398
main.gcodeSend(0x10a4ae00, 0x11, 0x109e2630, 0xa6)
	/home/pi/printer/app/gcode.go:28 +0xcc
main.printLayer()
	/home/pi/printer/app/printing.go:161 +0x4f4
main.startPlate(0x72, 0x1)
	/home/pi/printer/app/printing.go:70 +0x324
created by main.printerStart
	/home/pi/printer/app/web.go:627 +0x118

goroutine 23 [sleep]:
time.Sleep(0x540be400, 0x2)
	/usr/local/go/src/runtime/time.go:59 +0x104
main.(*monitorStruct).watch(0x766910)
	/home/pi/printer/app/slice-monitor.go:72 +0x414
created by main.main
	/home/pi/printer/app/server.go:49 +0xa0

goroutine 24 [syscall]:
syscall.Syscall(0x3, 0x4, 0x1092df00, 0x1, 0x1, 0x0, 0x0)
	/usr/local/go/src/syscall/asm_linux_arm.s:17 +0x8
syscall.read(0x4, 0x1092df00, 0x1, 0x1, 0x1, 0x0, 0x0)
	/usr/local/go/src/syscall/zsyscall_linux_arm.go:783 +0x78
syscall.Read(0x4, 0x1092df00, 0x1, 0x1, 0x1, 0x0, 0x0)
	/usr/local/go/src/syscall/syscall_unix.go:161 +0x4c
os.(*File).read(0x109a6278, 0x1092df00, 0x1, 0x1, 0x10a67780, 0x0, 0x0)
	/usr/local/go/src/os/file_unix.go:228 +0x54
os.(*File).Read(0x109a6278, 0x1092df00, 0x1, 0x1, 0x1, 0x0, 0x0)
	/usr/local/go/src/os/file.go:95 +0x7c
github.com/tarm/serial.(*Port).Read(0x109a6280, 0x1092df00, 0x1, 0x1, 0x10, 0x0, 0x0)
	/home/pi/go/src/github.com/tarm/serial/serial_posix.go:129 +0x50
_/home/pi/printer/app/shield.(*Conf).Read(0x757008, 0x1092df00, 0x1, 0x1, 0x1, 0x0, 0x0)
	/home/pi/printer/app/shield/shield.go:80 +0x9c
main.(*termStruct).readLine(0x757300, 0x0, 0x0, 0x0)
	/home/pi/printer/app/term.go:60 +0x104
main.(*termStruct).Reader(0x757300)
	/home/pi/printer/app/term.go:45 +0x40
created by main.main
	/home/pi/printer/app/server.go:50 +0xbc

goroutine 34 [IO wait, 2 minutes]:
net.runtime_pollWait(0x75a794f8, 0x72, 0x0)
	/usr/local/go/src/runtime/netpoll.go:160 +0x60
net.(*pollDesc).Wait(0x10956bf8, 0x72, 0x0, 0x0)
	/usr/local/go/src/net/fd_poll_runtime.go:73 +0x34
net.(*pollDesc).WaitRead(0x10956bf8, 0x0, 0x0)
	/usr/local/go/src/net/fd_poll_runtime.go:78 +0x30
net.(*netFD).readFrom(0x10956bc0, 0x1092fa9c, 0x400, 0x400, 0x0, 0x0, 0x0, 0x75a74078, 0x109100a8)
	/usr/local/go/src/net/fd_unix.go:277 +0x20c
net.(*UDPConn).ReadFromUDP(0x1090a5e0, 0x1092fa9c, 0x400, 0x400, 0x10995100, 0x185, 0x0, 0x0)
	/usr/local/go/src/net/udpsock_posix.go:61 +0xe4
_/home/pi/printer/app/ssdp.Server(0x519c58, 0x2, 0x109b28cf, 0x8)
	/home/pi/printer/app/ssdp/ssdp.go:56 +0x1b8
created by main.afterIP
	/home/pi/printer/app/server.go:70 +0x64

goroutine 36 [sleep]:
time.Sleep(0xf8475800, 0xd)
	/usr/local/go/src/runtime/time.go:59 +0x104
main.updateControlPanel()
	/home/pi/printer/app/server.go:132 +0x28
created by main.afterIP
	/home/pi/printer/app/server.go:72 +0xbc

trap    0x0
error   0x0
oldmask 0x0
r0      0x0
r1      0x4140
r2      0x6
r3      0x4140
r4      0x6
r5      0x2
r6      0x76da1bec
r7      0x10c
r8      0x11305680
r9      0x7cf0efb0
r10     0x10b112b0
fp      0x73daf8
ip      0x0
sp      0x7cf0ea94
lr      0x76ca18a8
pc      0x76ca18dc
cpsr    0x20000010
fault   0x0

Shahin

Administrator

Registered: 2016-02-17

Posts: 3,541

Re: Printer crashed just shy of finishing an 8h print

Adam,

Is it normal response from Trinamic drivers?
You are not on the latest build? Which build you are using?

Please, share /var/log/syslog file dump too.
Once such error has been reported and culprit was raspbian graphic stack which hijacked gpu access. Do you use full version of raspbian or lite version?

adam

Member

Registered: 2016-02-18

Posts: 100

Re: Printer crashed just shy of finishing an 8h print

- The response from Trinamic drivers is OK.
- I'm using Build 1039, is there a newer one?
- I use full raspbian.

/var/log$ cat /etc/os-release
PRETTY_NAME="Raspbian GNU/Linux 7 (wheezy)"
NAME="Raspbian GNU/Linux"
VERSION_ID="7"
VERSION="7 (wheezy)"
ID=raspbian
ID_LIKE=debian
ANSI_COLOR="1;31"
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"

Shahin

Administrator

Registered: 2016-02-17

Posts: 3,541

Re: Printer crashed just shy of finishing an 8h print

We have some new error recovery function unfortunately it still beta.

Could you share /var/log/syslog ?

adam

Member

Registered: 2016-02-18

Posts: 100

Re: Printer crashed just shy of finishing an 8h print

oh sry, i forgot

Mar 16 00:17:55 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 00:27:55 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 00:37:55 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 00:47:55 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 00:57:55 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 01:07:55 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 01:17:01 raspberrypi /USR/SBIN/CRON[7915]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Mar 16 01:17:55 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 01:27:55 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 01:37:55 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 01:47:55 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 01:57:55 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 02:07:55 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 02:17:01 raspberrypi /USR/SBIN/CRON[10857]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Mar 16 02:17:55 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 02:27:55 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 02:37:55 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 02:47:55 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 02:57:55 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 03:07:55 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 03:17:01 raspberrypi /USR/SBIN/CRON[13810]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Mar 16 03:17:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 03:27:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 03:37:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 03:47:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 03:57:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 04:07:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 04:17:01 raspberrypi /USR/SBIN/CRON[16768]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Mar 16 04:17:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 04:27:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 04:37:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 04:47:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 04:57:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 05:07:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 05:17:01 raspberrypi /USR/SBIN/CRON[19075]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Mar 16 05:17:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 05:27:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 05:37:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 05:47:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 05:57:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 06:07:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 06:17:01 raspberrypi /USR/SBIN/CRON[19088]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Mar 16 06:17:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 06:25:01 raspberrypi /USR/SBIN/CRON[19100]: (root) CMD (test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily ))
Mar 16 06:27:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 06:37:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 06:47:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 06:57:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 07:07:56 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 07:17:01 raspberrypi /USR/SBIN/CRON[19171]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Mar 16 07:17:57 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 07:27:57 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 07:37:41 raspberrypi kernel: [36301.482285] wlan0: AP c0:25:06:51:df:0a changed bandwidth, new config is 2412 MHz, width 2 (2422/0 MHz)
Mar 16 07:37:42 raspberrypi kernel: [36302.608683] wlan0: AP c0:25:06:51:df:0a changed bandwidth, new config is 2412 MHz, width 1 (2412/0 MHz)
Mar 16 07:37:44 raspberrypi kernel: [36304.451899] wlan0: AP c0:25:06:51:df:0a changed bandwidth, new config is 2412 MHz, width 2 (2422/0 MHz)
Mar 16 07:37:57 raspberrypi wpa_supplicant[1592]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 07:17:22 raspberrypi kernel: imklog 5.8.11, log source = /proc/kmsg started.
Mar 16 07:17:22 raspberrypi rsyslogd: [origin software="rsyslogd" swVersion="5.8.11" x-pid="2061" x-info="http://www.rsyslog.com"] start
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] Booting Linux on physical CPU 0xf00
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] Initializing cgroup subsys cpu
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] Initializing cgroup subsys cpuacct
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] Linux version 3.18.11-v7+ (dc4@dc4-XPS13-9333) (gcc version 4.8.3 20140303 (prerelease) (crosstool-NG linaro-1.13.1+bzr2650 - Linaro GCC 2014.03) ) #781 SMP PREEMPT Tue Apr 21 18:07:59 BST 2015
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] CPU: ARMv7 Processor [410fc075] revision 5 (ARMv7), cr=10c5387d
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] Machine model: Raspberry Pi 2 Model B
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] cma: Reserved 8 MiB at 0x36800000
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] Memory policy: Data cache writealloc
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] On node 0 totalpages: 225280
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] free_area_init_node: node 0, pgdat 8080f480, node_mem_map b6113000
Mar 16 07:17:22 raspberrypi kernel: [    0.000000]   Normal zone: 1760 pages used for memmap
Mar 16 07:17:22 raspberrypi kernel: [    0.000000]   Normal zone: 0 pages reserved
Mar 16 07:17:22 raspberrypi kernel: [    0.000000]   Normal zone: 225280 pages, LIFO batch:31
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] [bcm2709_smp_init_cpus] enter (8620->f3003010)
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] [bcm2709_smp_init_cpus] ncores=4
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] PERCPU: Embedded 10 pages/cpu @b60e1000 s11456 r8192 d21312 u40960
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] pcpu-alloc: s11456 r8192 d21312 u40960 alloc=10*4096
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 223520
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] Kernel command line: dma.dmachans=0x7f35 bcm2708_fb.fbwidth=1920 bcm2708_fb.fbheight=1080 bcm2709.boardrev=0xa01041 bcm2709.serial=0x5c50daa4 smsc95xx.macaddr=B8:27:EB:50:DA:A4 bcm2708_fb.fbswap=1 bcm2709.disk_led_gpio=47 bcm2709.disk_led_active_low=0 sdhci-bcm2708.emmc_clock_freq=250000000 vc_mem.mem_base=0x3dc00000 vc_mem.mem_size=0x3f000000  dwc_otg.lpm_enable=0 console=ttyAMA0,115200 console=tty1 root=/dev/mmcblk0p2 rootfstype=ext4 elevator=deadline rootwait
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes)
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] Memory: 875808K/901120K available (5722K kernel code, 397K rwdata, 1748K rodata, 384K init, 763K bss, 25312K reserved)
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] Virtual kernel memory layout:
Mar 16 07:17:22 raspberrypi kernel: [    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
Mar 16 07:17:22 raspberrypi kernel: [    0.000000]     fixmap  : 0xffc00000 - 0xffe00000   (2048 kB)
Mar 16 07:17:22 raspberrypi kernel: [    0.000000]     vmalloc : 0xb7800000 - 0xff000000   (1144 MB)
Mar 16 07:17:22 raspberrypi kernel: [    0.000000]     lowmem  : 0x80000000 - 0xb7000000   ( 880 MB)
Mar 16 07:17:22 raspberrypi kernel: [    0.000000]     modules : 0x7f000000 - 0x80000000   (  16 MB)
Mar 16 07:17:22 raspberrypi kernel: [    0.000000]       .text : 0x80008000 - 0x80753a48   (7471 kB)
Mar 16 07:17:22 raspberrypi kernel: [    0.000000]       .init : 0x80754000 - 0x807b4000   ( 384 kB)
Mar 16 07:17:22 raspberrypi kernel: [    0.000000]       .data : 0x807b4000 - 0x808174bc   ( 398 kB)
Mar 16 07:17:22 raspberrypi kernel: [    0.000000]        .bss : 0x808174bc - 0x808d6254   ( 764 kB)
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] Preemptible hierarchical RCU implementation.
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] NR_IRQS:608
Mar 16 07:17:22 raspberrypi kernel: [    0.000000] Architected cp15 timer(s) running at 19.20MHz (virt).
Mar 16 07:17:22 raspberrypi kernel: [    0.000013] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 3579139424256ns
Mar 16 07:17:22 raspberrypi kernel: [    0.000035] Switching to timer-based delay loop, resolution 52ns
Mar 16 07:17:22 raspberrypi kernel: [    0.000329] Console: colour dummy device 80x30
Mar 16 07:17:22 raspberrypi kernel: [    0.001761] console [tty1] enabled
Mar 16 07:17:22 raspberrypi kernel: [    0.001812] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
Mar 16 07:17:22 raspberrypi kernel: [    0.001895] pid_max: default: 32768 minimum: 301
Mar 16 07:17:22 raspberrypi kernel: [    0.002305] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
Mar 16 07:17:22 raspberrypi kernel: [    0.002365] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
Mar 16 07:17:22 raspberrypi kernel: [    0.003647] Initializing cgroup subsys memory
Mar 16 07:17:22 raspberrypi kernel: [    0.003735] Initializing cgroup subsys devices
Mar 16 07:17:22 raspberrypi kernel: [    0.003790] Initializing cgroup subsys freezer
Mar 16 07:17:22 raspberrypi kernel: [    0.003840] Initializing cgroup subsys net_cls
Mar 16 07:17:22 raspberrypi kernel: [    0.003905] Initializing cgroup subsys blkio
Mar 16 07:17:22 raspberrypi kernel: [    0.004013] CPU: Testing write buffer coherency: ok
Mar 16 07:17:22 raspberrypi kernel: [    0.004129] ftrace: allocating 19614 entries in 58 pages
Mar 16 07:17:22 raspberrypi kernel: [    0.052536] CPU0: update cpu_capacity 1024
Mar 16 07:17:22 raspberrypi kernel: [    0.052613] CPU0: thread -1, cpu 0, socket 15, mpidr 80000f00
Mar 16 07:17:22 raspberrypi kernel: [    0.052654] [bcm2709_smp_prepare_cpus] enter
Mar 16 07:17:22 raspberrypi kernel: [    0.052808] Setting up static identity map for 0x528478 - 0x5284ac
Mar 16 07:17:22 raspberrypi kernel: [    0.112448] [bcm2709_boot_secondary] cpu:1 started (0) 18
Mar 16 07:17:22 raspberrypi kernel: [    0.112766] CPU1: Booted secondary processor
Mar 16 07:17:22 raspberrypi kernel: [    0.112774] [bcm2709_secondary_init] enter cpu:1
Mar 16 07:17:22 raspberrypi kernel: [    0.112827] CPU1: update cpu_capacity 1024
Mar 16 07:17:22 raspberrypi kernel: [    0.112837] CPU1: thread -1, cpu 1, socket 15, mpidr 80000f01
Mar 16 07:17:22 raspberrypi kernel: [    0.132424] [bcm2709_boot_secondary] cpu:2 started (0) 16
Mar 16 07:17:22 raspberrypi kernel: [    0.132677] CPU2: Booted secondary processor
Mar 16 07:17:22 raspberrypi kernel: [    0.132684] [bcm2709_secondary_init] enter cpu:2
Mar 16 07:17:22 raspberrypi kernel: [    0.132718] CPU2: update cpu_capacity 1024
Mar 16 07:17:22 raspberrypi kernel: [    0.132727] CPU2: thread -1, cpu 2, socket 15, mpidr 80000f02
Mar 16 07:17:22 raspberrypi kernel: [    0.152508] [bcm2709_boot_secondary] cpu:3 started (0) 18
Mar 16 07:17:22 raspberrypi kernel: [    0.152744] CPU3: Booted secondary processor
Mar 16 07:17:22 raspberrypi kernel: [    0.152751] [bcm2709_secondary_init] enter cpu:3
Mar 16 07:17:22 raspberrypi kernel: [    0.152780] CPU3: update cpu_capacity 1024
Mar 16 07:17:22 raspberrypi kernel: [    0.152788] CPU3: thread -1, cpu 3, socket 15, mpidr 80000f03
Mar 16 07:17:22 raspberrypi kernel: [    0.152886] Brought up 4 CPUs
Mar 16 07:17:22 raspberrypi kernel: [    0.153006] SMP: Total of 4 processors activated (153.60 BogoMIPS).
Mar 16 07:17:22 raspberrypi kernel: [    0.153039] CPU: All CPU(s) started in SVC mode.
Mar 16 07:17:22 raspberrypi kernel: [    0.154048] devtmpfs: initialized
Mar 16 07:17:22 raspberrypi kernel: [    0.178897] VFP support v0.3: implementor 41 architecture 2 part 30 variant 7 rev 5
Mar 16 07:17:22 raspberrypi kernel: [    0.180885] pinctrl core: initialized pinctrl subsystem
Mar 16 07:17:22 raspberrypi kernel: [    0.184000] NET: Registered protocol family 16
Mar 16 07:17:22 raspberrypi kernel: [    0.189626] DMA: preallocated 4096 KiB pool for atomic coherent allocations
Mar 16 07:17:22 raspberrypi kernel: [    0.190800] bcm2709.uart_clock = 3000000
Mar 16 07:17:22 raspberrypi kernel: [    0.193755] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
Mar 16 07:17:22 raspberrypi kernel: [    0.193808] hw-breakpoint: maximum watchpoint size is 8 bytes.
Mar 16 07:17:22 raspberrypi kernel: [    0.193863] mailbox: Broadcom VideoCore Mailbox driver
Mar 16 07:17:22 raspberrypi kernel: [    0.193996] bcm2708_vcio: mailbox at f300b880
Mar 16 07:17:22 raspberrypi kernel: [    0.194358] bcm_power: Broadcom power driver
Mar 16 07:17:22 raspberrypi kernel: [    0.194394] bcm_power_open() -> 0
Mar 16 07:17:22 raspberrypi kernel: [    0.194419] bcm_power_request(0, 8)
Mar 16 07:17:22 raspberrypi kernel: [    0.695098] bcm_mailbox_read -> 00000080, 0
Mar 16 07:17:22 raspberrypi kernel: [    0.695131] bcm_power_request -> 0
Mar 16 07:17:22 raspberrypi kernel: [    0.695275] Serial: AMBA PL011 UART driver
Mar 16 07:17:22 raspberrypi kernel: [    0.695424] dev:f1: ttyAMA0 at MMIO 0x3f201000 (irq = 83, base_baud = 0) is a PL011 rev3
Mar 16 07:17:22 raspberrypi kernel: [    1.203787] console [ttyAMA0] enabled
Mar 16 07:17:22 raspberrypi kernel: [    1.275662] SCSI subsystem initialized
Mar 16 07:17:22 raspberrypi kernel: [    1.279678] usbcore: registered new interface driver usbfs
Mar 16 07:17:22 raspberrypi kernel: [    1.285351] usbcore: registered new interface driver hub
Mar 16 07:17:22 raspberrypi kernel: [    1.290817] usbcore: registered new device driver usb
Mar 16 07:17:22 raspberrypi kernel: [    1.297720] Switched to clocksource arch_sys_counter
Mar 16 07:17:22 raspberrypi kernel: [    1.333367] FS-Cache: Loaded
Mar 16 07:17:22 raspberrypi kernel: [    1.336603] CacheFiles: Loaded
Mar 16 07:17:22 raspberrypi kernel: [    1.351135] NET: Registered protocol family 2
Mar 16 07:17:22 raspberrypi kernel: [    1.356781] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
Mar 16 07:17:22 raspberrypi kernel: [    1.364039] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
Mar 16 07:17:22 raspberrypi kernel: [    1.370741] TCP: Hash tables configured (established 8192 bind 8192)
Mar 16 07:17:22 raspberrypi kernel: [    1.377210] TCP: reno registered
Mar 16 07:17:22 raspberrypi kernel: [    1.380487] UDP hash table entries: 512 (order: 2, 16384 bytes)
Mar 16 07:17:22 raspberrypi kernel: [    1.386472] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
Mar 16 07:17:22 raspberrypi kernel: [    1.393204] NET: Registered protocol family 1
Mar 16 07:17:22 raspberrypi kernel: [    1.398257] RPC: Registered named UNIX socket transport module.
Mar 16 07:17:22 raspberrypi kernel: [    1.404200] RPC: Registered udp transport module.
Mar 16 07:17:22 raspberrypi kernel: [    1.408970] RPC: Registered tcp transport module.
Mar 16 07:17:22 raspberrypi kernel: [    1.413689] RPC: Registered tcp NFSv4.1 backchannel transport module.
Mar 16 07:17:22 raspberrypi kernel: [    1.421136] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 5 counters available
Mar 16 07:17:22 raspberrypi kernel: [    1.429546] bcm2708_dma: DMA manager at f3007000
Mar 16 07:17:22 raspberrypi kernel: [    1.434338] vc-mem: phys_addr:0x00000000 mem_base=0x3dc00000 mem_size:0x3f000000(1008 MiB)
Mar 16 07:17:22 raspberrypi kernel: [    1.444163] futex hash table entries: 1024 (order: 4, 65536 bytes)
Mar 16 07:17:22 raspberrypi kernel: [    1.450685] audit: initializing netlink subsys (disabled)
Mar 16 07:17:22 raspberrypi kernel: [    1.456155] audit: type=2000 audit(1.239:1): initialized
Mar 16 07:17:22 raspberrypi kernel: [    1.477757] VFS: Disk quotas dquot_6.5.2
Mar 16 07:17:22 raspberrypi kernel: [    1.482068] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
Mar 16 07:17:22 raspberrypi kernel: [    1.491639] FS-Cache: Netfs 'nfs' registered for caching
Mar 16 07:17:22 raspberrypi kernel: [    1.498057] NFS: Registering the id_resolver key type
Mar 16 07:17:22 raspberrypi kernel: [    1.503186] Key type id_resolver registered
Mar 16 07:17:22 raspberrypi kernel: [    1.507381] Key type id_legacy registered
Mar 16 07:17:22 raspberrypi kernel: [    1.512588] msgmni has been set to 1726
Mar 16 07:17:22 raspberrypi kernel: [    1.518358] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
Mar 16 07:17:22 raspberrypi kernel: [    1.525959] io scheduler noop registered
Mar 16 07:17:22 raspberrypi kernel: [    1.529939] io scheduler deadline registered (default)
Mar 16 07:17:22 raspberrypi kernel: [    1.535407] io scheduler cfq registered
Mar 16 07:17:22 raspberrypi kernel: [    1.541876] BCM2708FB: allocated DMA memory f6c00000
Mar 16 07:17:22 raspberrypi kernel: [    1.546889] BCM2708FB: allocated DMA channel 0 @ f3007000
Mar 16 07:17:22 raspberrypi kernel: [    1.585936] Console: switching to colour frame buffer device 240x67
Mar 16 07:17:22 raspberrypi kernel: [    1.613617] bcm2708-dmaengine bcm2708-dmaengine: Load BCM2835 DMA engine driver
Mar 16 07:17:22 raspberrypi kernel: [    1.621399] uart-pl011 dev:f1: no DMA platform data
Mar 16 07:17:22 raspberrypi kernel: [    1.626874] vc-cma: Videocore CMA driver
Mar 16 07:17:22 raspberrypi kernel: [    1.630959] vc-cma: vc_cma_base      = 0x00000000
Mar 16 07:17:22 raspberrypi kernel: [    1.635755] vc-cma: vc_cma_size      = 0x00000000 (0 MiB)
Mar 16 07:17:22 raspberrypi kernel: [    1.641312] vc-cma: vc_cma_initial   = 0x00000000 (0 MiB)
Mar 16 07:17:22 raspberrypi kernel: [    1.658668] brd: module loaded
Mar 16 07:17:22 raspberrypi kernel: [    1.667477] loop: module loaded
Mar 16 07:17:22 raspberrypi kernel: [    1.671087] vchiq: vchiq_init_state: slot_zero = 0xb6800000, is_master = 0
Mar 16 07:17:22 raspberrypi kernel: [    1.678996] Loading iSCSI transport class v2.0-870.
Mar 16 07:17:22 raspberrypi kernel: [    1.684979] usbcore: registered new interface driver smsc95xx
Mar 16 07:17:22 raspberrypi kernel: [    1.690962] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
Mar 16 07:17:22 raspberrypi kernel: [    1.897135] Core Release: 2.80a
Mar 16 07:17:22 raspberrypi kernel: [    1.900388] Setting default values for core params
Mar 16 07:17:22 raspberrypi kernel: [    1.905312] Finished setting default values for core params
Mar 16 07:17:22 raspberrypi kernel: [    2.111408] Using Buffer DMA mode
Mar 16 07:17:22 raspberrypi kernel: [    2.114796] Periodic Transfer Interrupt Enhancement - disabled
Mar 16 07:17:22 raspberrypi kernel: [    2.120756] Multiprocessor Interrupt Enhancement - disabled
Mar 16 07:17:22 raspberrypi kernel: [    2.126431] OTG VER PARAM: 0, OTG VER FLAG: 0
Mar 16 07:17:22 raspberrypi kernel: [    2.130893] Dedicated Tx FIFOs mode
Mar 16 07:17:22 raspberrypi kernel: [    2.134819] WARN::dwc_otg_hcd_init:1047: FIQ DMA bounce buffers: virt = 0xb6c14000 dma = 0xf6c14000 len=9024
Mar 16 07:17:22 raspberrypi kernel: [    2.144882] FIQ FSM acceleration enabled for :
Mar 16 07:17:22 raspberrypi kernel: [    2.144882] Non-periodic Split Transactions
Mar 16 07:17:22 raspberrypi kernel: [    2.144882] Periodic Split Transactions
Mar 16 07:17:22 raspberrypi kernel: [    2.144882] High-Speed Isochronous Endpoints
Mar 16 07:17:22 raspberrypi kernel: [    2.161877] dwc_otg: Microframe scheduler enabled
Mar 16 07:17:22 raspberrypi kernel: [    2.161944] WARN::hcd_init_fiq:412: FIQ on core 1 at 0x803d98b4
Mar 16 07:17:22 raspberrypi kernel: [    2.167981] WARN::hcd_init_fiq:413: FIQ ASM at 0x803d9c10 length 36
Mar 16 07:17:22 raspberrypi kernel: [    2.174365] WARN::hcd_init_fiq:438: MPHI regs_base at 0xb780a000
Mar 16 07:17:22 raspberrypi kernel: [    2.180518] dwc_otg bcm2708_usb: DWC OTG Controller
Mar 16 07:17:22 raspberrypi kernel: [    2.185531] dwc_otg bcm2708_usb: new USB bus registered, assigned bus number 1
Mar 16 07:17:22 raspberrypi kernel: [    2.192941] dwc_otg bcm2708_usb: irq 32, io mem 0x00000000
Mar 16 07:17:22 raspberrypi kernel: [    2.198594] Init: Port Power? op_state=1
Mar 16 07:17:22 raspberrypi kernel: [    2.207820] Init: Power Port (0)
Mar 16 07:17:22 raspberrypi kernel: [    2.216508] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
Mar 16 07:17:22 raspberrypi kernel: [    2.228576] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Mar 16 07:17:22 raspberrypi kernel: [    2.241068] usb usb1: Product: DWC OTG Controller
Mar 16 07:17:22 raspberrypi kernel: [    2.251032] usb usb1: Manufacturer: Linux 3.18.11-v7+ dwc_otg_hcd
Mar 16 07:17:22 raspberrypi kernel: [    2.262459] usb usb1: SerialNumber: bcm2708_usb
Mar 16 07:17:22 raspberrypi kernel: [    2.273238] hub 1-0:1.0: USB hub found
Mar 16 07:17:22 raspberrypi kernel: [    2.282378] hub 1-0:1.0: 1 port detected
Mar 16 07:17:22 raspberrypi kernel: [    2.292002] dwc_otg: FIQ enabled
Mar 16 07:17:22 raspberrypi kernel: [    2.292017] dwc_otg: NAK holdoff enabled
Mar 16 07:17:22 raspberrypi kernel: [    2.292028] dwc_otg: FIQ split-transaction FSM enabled
Mar 16 07:17:22 raspberrypi kernel: [    2.292068] Module dwc_common_port init
Mar 16 07:17:22 raspberrypi kernel: [    2.292460] usbcore: registered new interface driver usb-storage
Mar 16 07:17:22 raspberrypi kernel: [    2.304073] mousedev: PS/2 mouse device common for all mice
Mar 16 07:17:22 raspberrypi kernel: [    2.315509] bcm2835-cpufreq: min=600000 max=900000
Mar 16 07:17:22 raspberrypi kernel: [    2.325912] sdhci: Secure Digital Host Controller Interface driver
Mar 16 07:17:22 raspberrypi kernel: [    2.337270] sdhci: Copyright(c) Pierre Ossman
Mar 16 07:17:22 raspberrypi kernel: [    2.346974] DMA channels allocated for the MMC driver
Mar 16 07:17:22 raspberrypi kernel: [    2.387763] Load BCM2835 MMC driver
Mar 16 07:17:22 raspberrypi kernel: [    2.403816] sdhci-pltfm: SDHCI platform and OF driver helper
Mar 16 07:17:22 raspberrypi kernel: [    2.415298] ledtrig-cpu: registered to indicate activity on CPUs
Mar 16 07:17:22 raspberrypi kernel: [    2.426721] hidraw: raw HID events driver (C) Jiri Kosina
Mar 16 07:17:22 raspberrypi kernel: [    2.438625] usbcore: registered new interface driver usbhid
Mar 16 07:17:22 raspberrypi kernel: [    2.449402] usbhid: USB HID core driver
Mar 16 07:17:22 raspberrypi kernel: [    2.459741] TCP: cubic registered
Mar 16 07:17:22 raspberrypi kernel: [    2.469284] Initializing XFRM netlink socket
Mar 16 07:17:22 raspberrypi kernel: [    2.478748] NET: Registered protocol family 17
Mar 16 07:17:22 raspberrypi kernel: [    2.488479] Key type dns_resolver registered
Mar 16 07:17:22 raspberrypi kernel: [    2.497870] Indeed it is in host mode hprt0 = 00021501
Mar 16 07:17:22 raspberrypi kernel: [    2.498301] Registering SWP/SWPB emulation handler
Mar 16 07:17:22 raspberrypi kernel: [    2.509044] registered taskstats version 1
Mar 16 07:17:22 raspberrypi kernel: [    2.509333] vc-sm: Videocore shared memory driver
Mar 16 07:17:22 raspberrypi kernel: [    2.509346] [vc_sm_connected_init]: start
Mar 16 07:17:22 raspberrypi kernel: [    2.518843] [vc_sm_connected_init]: end - returning 0
Mar 16 07:17:22 raspberrypi kernel: [    2.527217] mmc0: host does not support reading read-only switch, assuming write-enable
Mar 16 07:17:22 raspberrypi kernel: [    2.531200] mmc0: new high speed SDHC card at address aaaa
Mar 16 07:17:22 raspberrypi kernel: [    2.531779] mmcblk0: mmc0:aaaa SL08G 7.40 GiB 
Mar 16 07:17:22 raspberrypi kernel: [    2.533365]  mmcblk0: p1 p2
Mar 16 07:17:22 raspberrypi kernel: [    2.599817] EXT4-fs (mmcblk0p2): INFO: recovery required on readonly filesystem
Mar 16 07:17:22 raspberrypi kernel: [    2.612432] EXT4-fs (mmcblk0p2): write access will be enabled during recovery
Mar 16 07:17:22 raspberrypi kernel: [    2.767828] usb 1-1: new high-speed USB device number 2 using dwc_otg
Mar 16 07:17:22 raspberrypi kernel: [    2.779855] Indeed it is in host mode hprt0 = 00001101
Mar 16 07:17:22 raspberrypi kernel: [    2.988222] usb 1-1: New USB device found, idVendor=0424, idProduct=9514
Mar 16 07:17:22 raspberrypi kernel: [    3.000325] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Mar 16 07:17:22 raspberrypi kernel: [    3.013724] hub 1-1:1.0: USB hub found
Mar 16 07:17:22 raspberrypi kernel: [    3.022940] hub 1-1:1.0: 5 ports detected
Mar 16 07:17:22 raspberrypi kernel: [    3.307994] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
Mar 16 07:17:22 raspberrypi kernel: [    3.418310] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
Mar 16 07:17:22 raspberrypi kernel: [    3.430647] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Mar 16 07:17:22 raspberrypi kernel: [    3.446218] smsc95xx v1.0.4
Mar 16 07:17:22 raspberrypi kernel: [    3.512040] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-bcm2708_usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:50:da:a4
Mar 16 07:17:22 raspberrypi kernel: [    3.545807] EXT4-fs (mmcblk0p2): recovery complete
Mar 16 07:17:22 raspberrypi kernel: [    3.562374] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
Mar 16 07:17:22 raspberrypi kernel: [    3.576032] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
Mar 16 07:17:22 raspberrypi kernel: [    3.589201] devtmpfs: mounted
Mar 16 07:17:22 raspberrypi kernel: [    3.598196] Freeing unused kernel memory: 384K (80754000 - 807b4000)
Mar 16 07:17:22 raspberrypi kernel: [    3.607909] usb 1-1.2: new high-speed USB device number 4 using dwc_otg
Mar 16 07:17:22 raspberrypi kernel: [    3.725434] usb 1-1.2: New USB device found, idVendor=148f, idProduct=5370
Mar 16 07:17:22 raspberrypi kernel: [    3.738077] usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Mar 16 07:17:22 raspberrypi kernel: [    3.750975] usb 1-1.2: Product: 802.11 n WLAN
Mar 16 07:17:22 raspberrypi kernel: [    3.760917] usb 1-1.2: Manufacturer: Ralink
Mar 16 07:17:22 raspberrypi kernel: [    3.770705] usb 1-1.2: SerialNumber: 1.0
Mar 16 07:17:22 raspberrypi kernel: [    3.877985] usb 1-1.3: new full-speed USB device number 5 using dwc_otg
Mar 16 07:17:22 raspberrypi kernel: [    3.991924] usb 1-1.3: New USB device found, idVendor=16d0, idProduct=0653
Mar 16 07:17:22 raspberrypi kernel: [    4.005018] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Mar 16 07:17:22 raspberrypi kernel: [    4.018270] usb 1-1.3: Product: TMCM-1110 stepRocker
Mar 16 07:17:22 raspberrypi kernel: [    4.029170] usb 1-1.3: Manufacturer: Trinamic Motion Control
Mar 16 07:17:22 raspberrypi kernel: [    4.041136] usb 1-1.3: SerialNumber: TMCM-1110
Mar 16 07:17:22 raspberrypi kernel: [    5.165971] cdc_acm 1-1.3:1.0: This device cannot do calls on its own. It is not a modem.
Mar 16 07:17:22 raspberrypi kernel: [    5.258193] cdc_acm 1-1.3:1.0: ttyACM0: USB ACM device
Mar 16 07:17:22 raspberrypi kernel: [    5.298324] usbcore: registered new interface driver cdc_acm
Mar 16 07:17:22 raspberrypi kernel: [    5.311600] bcm2708_i2c_init_pinmode(1,2)
Mar 16 07:17:22 raspberrypi kernel: [    5.312473] cfg80211: Calling CRDA to update world regulatory domain
Mar 16 07:17:22 raspberrypi kernel: [    5.312682] cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters
Mar 16 07:17:22 raspberrypi kernel: [    5.349339] bcm2708_i2c_init_pinmode(1,3)
Mar 16 07:17:22 raspberrypi kernel: [    5.360011] bcm2708_i2c 3f804000.i2c: BSC1 Controller at 0x3f804000 (irq 79) (baudrate 100000)
Mar 16 07:17:22 raspberrypi kernel: [    5.441043] random: nonblocking pool is initialized
Mar 16 07:17:22 raspberrypi kernel: [    5.588177] usb 1-1.2: reset high-speed USB device number 4 using dwc_otg
Mar 16 07:17:22 raspberrypi kernel: [    5.768981] ieee80211 phy0: rt2x00_set_rt: Info - RT chipset 5390, rev 0502 detected
Mar 16 07:17:22 raspberrypi kernel: [    5.807279] ieee80211 phy0: rt2x00_set_rf: Info - RF chipset 5370 detected
Mar 16 07:17:22 raspberrypi kernel: [    5.842847] ieee80211 phy0: Selected rate control algorithm 'minstrel_ht'
Mar 16 07:17:22 raspberrypi kernel: [    5.844934] usbcore: registered new interface driver rt2800usb
Mar 16 07:17:22 raspberrypi kernel: [    7.326317] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
Mar 16 07:17:22 raspberrypi kernel: [    7.584324] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
Mar 16 07:17:22 raspberrypi kernel: [    8.169392] i2c /dev entries driver
Mar 16 07:17:22 raspberrypi kernel: [   12.041730] ieee80211 phy0: rt2x00lib_request_firmware: Info - Loading firmware file 'rt2870.bin'
Mar 16 07:17:22 raspberrypi kernel: [   12.044505] ieee80211 phy0: rt2x00lib_request_firmware: Info - Firmware detected - version: 0.29
Mar 16 07:17:22 raspberrypi kernel: [   12.641422] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
Mar 16 07:17:22 raspberrypi kernel: [   13.755537] cfg80211: Calling CRDA to update world regulatory domain
Mar 16 07:17:22 raspberrypi kernel: [   13.998773] wlan0: authenticate with c0:25:06:51:df:0a
Mar 16 07:17:22 raspberrypi kernel: [   14.045251] wlan0: send auth to c0:25:06:51:df:0a (try 1/3)
Mar 16 07:17:22 raspberrypi kernel: [   14.050039] wlan0: authenticated
Mar 16 07:17:22 raspberrypi kernel: [   14.057788] wlan0: associate with c0:25:06:51:df:0a (try 1/3)
Mar 16 07:17:22 raspberrypi kernel: [   14.063778] wlan0: RX AssocResp from c0:25:06:51:df:0a (capab=0x431 status=0 aid=4)
Mar 16 07:17:22 raspberrypi kernel: [   14.071757] wlan0: associated
Mar 16 07:17:22 raspberrypi kernel: [   14.076880] cfg80211: Calling CRDA to update world regulatory domain
Mar 16 07:17:23 raspberrypi /usr/sbin/cron[2223]: (CRON) INFO (pidfile fd = 3)
Mar 16 07:17:23 raspberrypi /usr/sbin/cron[2226]: (CRON) STARTUP (fork ok)
Mar 16 07:17:23 raspberrypi ntpd[2212]: ntpd 4.2.6p5@1.2349-o Sun Apr 12 22:37:22 UTC 2015 (1)
Mar 16 07:17:23 raspberrypi ntpd[2228]: proto: precision = 1.250 usec
Mar 16 07:17:23 raspberrypi /usr/sbin/cron[2226]: (CRON) INFO (Running @reboot jobs)
Mar 16 07:17:23 raspberrypi ntpd[2228]: Listen and drop on 0 v4wildcard 0.0.0.0 UDP 123
Mar 16 07:17:23 raspberrypi ntpd[2228]: Listen normally on 1 lo 127.0.0.1 UDP 123
Mar 16 07:17:23 raspberrypi ntpd[2228]: Listen normally on 2 wlan0 192.168.178.75 UDP 123
Mar 16 07:17:23 raspberrypi ntpd[2228]: peers refreshed
Mar 16 07:17:23 raspberrypi ntpd[2228]: Listening on routing socket on fd #19 for interface updates
Mar 16 07:17:23 raspberrypi ntpd[2228]: restrict: error in address '::' on line 41. Ignoring...
Mar 16 07:17:23 raspberrypi ntpd[2228]: restrict: error in address '::1' on line 45. Ignoring...
Mar 16 07:17:23 raspberrypi kernel: [   28.362477] Adding 102396k swap on /var/swap.  Priority:-1 extents:2 across:2134012k SSFS
Mar 16 07:17:23 raspberrypi avahi-daemon[2314]: Found user 'avahi' (UID 103) and group 'avahi' (GID 105).
Mar 16 07:17:23 raspberrypi avahi-daemon[2314]: Successfully dropped root privileges.
Mar 16 07:17:23 raspberrypi avahi-daemon[2314]: avahi-daemon 0.6.31 starting up.
Mar 16 07:17:23 raspberrypi avahi-daemon[2314]: Successfully called chroot().
Mar 16 07:17:23 raspberrypi avahi-daemon[2314]: Successfully dropped remaining capabilities.
Mar 16 07:17:23 raspberrypi avahi-daemon[2314]: Loading service file /services/udisks.service.
Mar 16 07:17:23 raspberrypi avahi-daemon[2314]: socket() failed: Address family not supported by protocol
Mar 16 07:17:23 raspberrypi avahi-daemon[2314]: Failed to create IPv6 socket, proceeding in IPv4 only mode
Mar 16 07:17:23 raspberrypi avahi-daemon[2314]: socket() failed: Address family not supported by protocol
Mar 16 07:17:23 raspberrypi avahi-daemon[2314]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.178.75.
Mar 16 07:17:23 raspberrypi avahi-daemon[2314]: New relevant interface wlan0.IPv4 for mDNS.
Mar 16 07:17:23 raspberrypi avahi-daemon[2314]: Network interface enumeration completed.
Mar 16 07:17:23 raspberrypi avahi-daemon[2314]: Registering new address record for 192.168.178.75 on wlan0.IPv4.
Mar 16 07:17:23 raspberrypi avahi-daemon[2314]: Registering HINFO record with values 'ARMV7L'/'LINUX'.
Mar 16 07:17:24 raspberrypi avahi-daemon[2314]: Server startup complete. Host name is raspberrypi.local. Local service cookie is 1629664261.
Mar 16 07:17:25 raspberrypi avahi-daemon[2314]: Service "raspberrypi" (/services/udisks.service) successfully established.
Mar 16 07:42:44 raspberrypi kernel: [  178.267541] wlan0: AP c0:25:06:51:df:0a changed bandwidth, new config is 2412 MHz, width 1 (2412/0 MHz)
Mar 16 07:47:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 07:57:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 08:07:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 08:17:01 raspberrypi /USR/SBIN/CRON[2376]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Mar 16 08:17:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 08:27:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 08:37:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 08:47:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 08:57:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 09:07:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 09:17:01 raspberrypi /USR/SBIN/CRON[2394]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Mar 16 09:17:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 09:27:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 09:37:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 09:47:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 09:57:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 10:07:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 10:17:01 raspberrypi /USR/SBIN/CRON[2416]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Mar 16 10:17:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 10:27:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 10:37:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 10:47:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 10:57:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 11:07:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 11:17:01 raspberrypi /USR/SBIN/CRON[2436]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Mar 16 11:17:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 11:27:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 11:37:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 11:47:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 11:57:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 12:07:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 12:17:01 raspberrypi /USR/SBIN/CRON[2459]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Mar 16 12:17:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 12:27:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 12:37:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 12:47:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 12:57:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 13:07:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 13:17:01 raspberrypi /USR/SBIN/CRON[2478]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Mar 16 13:17:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 13:27:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 13:37:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 13:47:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 13:57:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 14:07:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 14:17:01 raspberrypi /USR/SBIN/CRON[2514]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Mar 16 14:17:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 14:27:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 14:37:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 14:47:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 14:57:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 15:07:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 15:17:01 raspberrypi /USR/SBIN/CRON[2537]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Mar 16 15:17:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 15:27:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 15:37:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 15:47:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 15:57:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 16:07:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 16:17:01 raspberrypi /USR/SBIN/CRON[2571]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Mar 16 16:17:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 16:27:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 16:37:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 16:47:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 16:57:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 17:07:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 17:17:01 raspberrypi /USR/SBIN/CRON[2593]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Mar 16 17:17:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 17:27:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 17:37:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 17:47:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 16 17:57:57 raspberrypi wpa_supplicant[1590]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]

adam

Member

Registered: 2016-02-18

Posts: 100

Re: Printer crashed just shy of finishing an 8h print

i am willing to text any beta functionality as always.

Shahin

Administrator

Registered: 2016-02-17

Posts: 3,541

Re: Printer crashed just shy of finishing an 8h print

Thanks, Adam

Based on what I have read it could be upstream providers bug, upgrade to beta version could solve the problem completely as our beta compiled with a newer version.
I will try to reproduce bug by keep dry printing continuously. Let see if I could find any clue.

Shahin

Administrator

Registered: 2016-02-17

Posts: 3,541

Re: Printer crashed just shy of finishing an 8h print

Adam,

I have employed couple of things to prevent it happens again. During my own tests in worst case scenario instead of crashes it should slow down system. It something to do with slow system calls and stalled processes.
I have add a new indicator in front of CPU usage. Indicate number of process currently being used. If it jumps from under 20 to 100~1000, there is something wrong, most likely external scripts which being called do not exit correctly.
It is a result of external factor (Kernel,OS,Compiler and etc) so we could not prevent it completely as long as we execute external programs. Probably gets fixed on its own down the road.

adam

Member

Registered: 2016-02-18

Posts: 100

Re: Printer crashed just shy of finishing an 8h print

alright, thanks. I will report back once I have some more long prints (Planning to do 25h+ soon). Maybe RPi3 will be better, I've already ordered one.

adam

Member

Registered: 2016-02-18

Posts: 100

Re: Printer crashed just shy of finishing an 8h print

Hi,
i've started a 25h print for overnight+ printing yesterday.
Now, after approx 10h the printer crashed..here's what i got from the logs:

Build 1074

PRINTER.LOG:

2016/03/21 10:12:15.765307 {"Layer":"2474","module":"Image","level":"Warning","msg":"Display layer public/plates/122/2474.png "}
2016/03/21 10:12:30.589577 {"Layer":"2475","module":"Image","level":"Warning","msg":"Display layer public/plates/122/2475.png "}
2016/03/21 10:12:45.409594 {"Layer":"2476","module":"Image","level":"Warning","msg":"Display layer public/plates/122/2476.png "}
2016/03/21 10:13:00.225378 {"Layer":"2477","module":"Image","level":"Warning","msg":"Display layer public/plates/122/2477.png "}
2016/03/21 10:13:15.099866 {"Layer":"2478","module":"Image","level":"Warning","msg":"Display layer public/plates/122/2478.png "}
2016/03/21 10:13:29.971549 {"Layer":"2479","module":"Image","level":"Warning","msg":"Display layer public/plates/122/2479.png "}
2016/03/21 10:14:04.432780 {"Layer":"2480","module":"Image","level":"Warning","msg":"Display layer public/plates/122/2480.png "}
image: memory exhausted

SYSLOG:

Mar 21 09:48:13 raspberrypi wpa_supplicant[1591]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 21 09:58:13 raspberrypi wpa_supplicant[1591]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 21 10:08:13 raspberrypi wpa_supplicant[1591]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 21 10:17:01 raspberrypi /USR/SBIN/CRON[3474]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Mar 21 10:18:13 raspberrypi wpa_supplicant[1591]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 21 10:28:13 raspberrypi wpa_supplicant[1591]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 21 10:38:13 raspberrypi wpa_supplicant[1591]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 21 10:48:13 raspberrypi wpa_supplicant[1591]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 21 10:58:13 raspberrypi wpa_supplicant[1591]: wlan0: WPA: Group rekeying completed with c0:25:06:51:df:0a [GTK=CCMP]
Mar 21 11:05:12 raspberrypi shutdown[3519]: shutting down for system reboot                /////////////////////////////////// this is where i manually rebooted because the GUI was not responsive.
Mar 21 11:05:12 raspberrypi init: Switching to runlevel: 6
Mar 21 11:05:13 raspberrypi avahi-daemon[2317]: Got SIGTERM, quitting.

Shahin

Administrator

Registered: 2016-02-17

Posts: 3,541

Re: Printer crashed just shy of finishing an 8h print

Adam,

I have recently have printed a plate with more than 10000 layers. Also with build you are using I have dry run at-least 20 prints without restart to make sure there is no leaks.
I think more likely cause of the problems are external scripts which you are currently using. I will send you email to troubleshoot the problem.

juliendelnatte

Member

Registered: 2017-06-07

Posts: 84

Re: Printer crashed just shy of finishing an 8h print

Hello I have the same problem on a raspberry pi 2.

Here are the last log :

2017/07/08 19:24:37.943073 {"Layer":"193","module":"GPIO","level":"Notice","msg":"Set Pin 19 to True"}
2017/07/08 19:24:38.042493 {"Layer":"193","module":"Image","level":"Warning","msg":"Display layer public/plates/3/193.png"}
image: memory exhausted

I print with a 2K 5"5 screen. It crash on every print with this problem.

Shahin

Administrator

Registered: 2016-02-17

Posts: 3,541

Re: Printer crashed just shy of finishing an 8h print

Could you take a picture of dashboard after crash also debug file.

juliendelnatte

Member

Registered: 2017-06-07

Posts: 84

Re: Printer crashed just shy of finishing an 8h print

the pi crash, I don't have access to the dashboard after this.

here are debug files : https://we.tl/rl4577HSnz

juliendelnatte

Member

Registered: 2017-06-07

Posts: 84

Re: Printer crashed just shy of finishing an 8h print

I think it's a better debug files here : https://we.tl/K89BodqrQw

I run a 1h print and everything work great. I run juste after a 4h print and after 31 layer, it crash. There is a lot of crash line in the printer.log file

Shahin

Administrator

Registered: 2016-02-17

Posts: 3,541

Re: Printer crashed just shy of finishing an 8h print

If you keep dashboard open, when it crashes you could see latest state of the resource usage.
Unfortunately right now wetransfer is down.

juliendelnatte

Member

Registered: 2017-06-07

Posts: 84

Re: Printer crashed just shy of finishing an 8h print

It crash this morning just by moving the Z axis... When I do a top on my pi, the printer process take up to 90% when moving the stepper (I use direct control). is moving the stepper a CPU consuming process?

Here from google drive : https://drive.google.com/file/d/0B2gsAc … sp=sharing

Shahin

Administrator

Registered: 2016-02-17

Posts: 3,541

Re: Printer crashed just shy of finishing an 8h print

90% is too high. Could you get debug file when it reaches 90%?

Outside of 90% everything else looks normal, I suspect power supply and SD card.

juliendelnatte

Member

Registered: 2017-06-07

Posts: 84

Re: Printer crashed just shy of finishing an 8h print

Ok, I'll try on another SD card, new installation,... It's possible because I reinstalled everything friday and never get this problem before.

juliendelnatte

Member

Registered: 2017-06-07

Posts: 84

Re: Printer crashed just shy of finishing an 8h print

I tested with another SD card, same probleme, another raspberry pi, same probleme,... without the beta distribution and same probleme... I'll test tomorrow with another alimentation... It only appends when I switched to a 2K screen...

edit : the ssh connexion still work and the printer.log show this :

runtime/cgo: pthread_create failed: Resource temporarily unavailable
SIGABRT: abort
PC=0x76cedf70runtime/cgo:  m=37pthread_create failed: Resource temporarily unavailable sigcode=
4294967290

goroutine 0 [idle]:

goroutine 34 [syscall]:
runtime.notetsleepg(0x6bf05c, 0x8c895, 0x0, 0x0)
    /usr/local/go/src/runtime/lock_futex.go:205 +0x2c fp=0x10a1c794 sp=0x10a1c77c
runtime.timerproc()
    /usr/local/go/src/runtime/time.go:209 +0x464 fp=0x10a1c7ec sp=0x10a1c794
runtime.goexit()
    /usr/local/go/src/runtime/asm_arm.s:1017 +0x4 fp=0x10a1c7ec sp=0x10a1c7ec
created by runtime.addtimerLocked
    /usr/local/go/src/runtime/time.go:116 +0x124

goroutine 1 [IO wait]:
net.runtime_pollWait(0x75276f78, 0x72, 0x0)
    /usr/local/go/src/runtime/netpoll.go:164 +0x44
net.(*pollDesc).wait(0x10b32dfc, 0x72, 0x695a00, 0x10ae06c0)
    /usr/local/go/src/net/fd_poll_runtime.go:75 +0x28
net.(*pollDesc).waitRead(0x10b32dfc, 0xffffffff, 0x0)
    /usr/local/go/src/net/fd_poll_runtime.go:80 +0x24
net.(*netFD).accept(0x10b32dc0, 0x0, 0x697280, 0x10ae06c0)
    /usr/local/go/src/net/fd_unix.go:430 +0x15c
net.(*TCPListener).accept(0x10ae2048, 0x24c430, 0x10b93cbc, 0x62694)
    /usr/local/go/src/net/tcpsock_posix.go:136 +0x20
net.(*TCPListener).Accept(0x10ae2048, 0x4b7890, 0x10b2c060, 0x699f50, 0x10b1a2c0)
    /usr/local/go/src/net/tcpsock.go:228 +0x3c
net/http.(*Server).Serve(0x10a60900, 0x699708, 0x10ae2048, 0x0, 0x0)
    /usr/local/go/src/net/http/server.go:2643 +0x1ac
github.com/tylerb/graceful.(*Server).Serve(0x10a78e70, 0x699708, 0x10ae2048, 0x699708, 0x10ae2048)
    /home/pi/go/src/github.com/tylerb/graceful/graceful.go:307 +0x2c4
github.com/tylerb/graceful.(*Server).ListenAndServe(0x10a78e70, 0x4a8b50, 0x1f)
    /home/pi/go/src/github.com/tylerb/graceful/graceful.go:147 +0x78
github.com/labstack/echo.(*Echo).StartServer(0x10ac8370, 0x10a60900, 0x1, 0x10aef2fa)
    /home/pi/go/src/github.com/labstack/echo/echo.go:554 +0x35c
main.webInit()
    /home/pi/printer/app/routes.go:155 +0x3038
main.main()
    /home/pi/printer/app/server.go:79 +0x248

goroutine 17 [syscall, 86 minutes, locked to thread]:
runtime.goexit()
    /usr/local/go/src/runtime/asm_arm.s:1017 +0x4

goroutine 20 [syscall, 86 minutes]:
os/signal.signal_recv(0x0)
    /usr/local/go/src/runtime/sigqueue.go:116 +0x154
os/signal.loop()
    /usr/local/go/src/os/signal/signal_unix.go:22 +0x14
created by os/signal.init.1
    /usr/local/go/src/os/signal/signal_unix.go:28 +0x30

goroutine 21 [sleep]:
time.Sleep(0x1a55c1, 0x0)
    /usr/local/go/src/runtime/time.go:59 +0x10c
projects/printer/app/move.(*speedStruct).traditionalCalc(0x6bf2d8)
    /home/pi/go/src/projects/printer/app/move/speed.go:141 +0xc8
projects/printer/app/move.(*speedStruct).calc(0x6bf2d8, 0x10a62380)
    /home/pi/go/src/projects/printer/app/move/speed.go:95 +0x5c
created by projects/printer/app/move.init.1
    /home/pi/go/src/projects/printer/app/move/speed.go:29 +0x38

goroutine 23 [chan receive]:
main.(*StatusStruct).FindIP(0x6bf4c0)
    /home/pi/printer/app/db.go:563 +0x60
created by main.(*StatusStruct).Load
    /home/pi/printer/app/db.go:543 +0x50

goroutine 3 [chan receive]:
main.wifiStatus()
    /home/pi/printer/app/wireless.go:80 +0xf4
created by main.wifiConnect
    /home/pi/printer/app/wireless.go:23 +0xc4

goroutine 29 [sleep]:
time.Sleep(0x5f5e100, 0x0)
    /usr/local/go/src/runtime/time.go:59 +0x10c
main.(*termStruct).readLine(0x6bee68, 0x8, 0x435800, 0x10a0e018)
    /home/pi/printer/app/term.go:48 +0x2b8
main.(*termStruct).Reader(0x6bee68)
    /home/pi/printer/app/term.go:37 +0xa8
created by main.main
    /home/pi/printer/app/server.go:57 +0x134

goroutine 30 [chan receive]:
main.(*monitorStruct).watch(0x6ce510)
    /home/pi/printer/app/slice-monitor.go:46 +0x7c
created by main.main
    /home/pi/printer/app/server.go:58 +0x150

goroutine 32 [chan receive]:
projects/printer/app/hw/monitor.Monitor()
    /home/pi/go/src/projects/printer/app/hw/monitor/monitor_linux.go:33 +0x7c
created by main.main
    /home/pi/printer/app/server.go:64 +0x260

goroutine 35 [select]:
github.com/tylerb/graceful.(*Server).manageConnections(0x10a78e70, 0x10ade100, 0x10ade140, 0x10ade180, 0x10ade1c0, 0x10ade200, 0x10ade240)
    /home/pi/go/src/github.com/tylerb/graceful/graceful.go:364 +0x6a8
created by github.com/tylerb/graceful.(*Server).Serve
    /home/pi/go/src/github.com/tylerb/graceful/graceful.go:295 +0x224

goroutine 36 [select, 86 minutes, locked to thread]:
runtime.gopark(0x4b7bcc, 0x0, 0x49b50d, 0x6, 0x18, 0x2)
    /usr/local/go/src/runtime/proc.go:271 +0xfc
runtime.selectgoImpl(0x10b40fa0, 0x0, 0xc)
    /usr/local/go/src/runtime/select.go:423 +0x119c
runtime.selectgo(0x10b40fa0)
    /usr/local/go/src/runtime/select.go:238 +0x10
runtime.ensureSigM.func1()
    /usr/local/go/src/runtime/signal_unix.go:434 +0x2bc
runtime.goexit()
    /usr/local/go/src/runtime/asm_arm.s:1017 +0x4

goroutine 37 [chan receive, 86 minutes]:
github.com/tylerb/graceful.(*Server).handleInterrupt(0x10a78e70, 0x10ade280, 0x10ade380, 0x699708, 0x10ae2048)
    /home/pi/go/src/github.com/tylerb/graceful/graceful.go:419 +0x38
created by github.com/tylerb/graceful.(*Server).Serve
    /home/pi/go/src/github.com/tylerb/graceful/graceful.go:303 +0x2a4

goroutine 56 [IO wait]:
net.runtime_pollWait(0x75276c30, 0x72, 0x0)
    /usr/local/go/src/runtime/netpoll.go:164 +0x44
net.(*pollDesc).wait(0x10a1043c, 0x72, 0x0, 0x0)
    /usr/local/go/src/net/fd_poll_runtime.go:75 +0x28
net.(*pollDesc).waitRead(0x10a1043c, 0x10b9fadc, 0x400)
    /usr/local/go/src/net/fd_poll_runtime.go:80 +0x24
net.(*netFD).readFrom(0x10a10400, 0x10b9fadc, 0x400, 0x400, 0x0, 0x0, 0x0, 0x697c58, 0x695a00)
    /usr/local/go/src/net/fd_unix.go:277 +0x13c
net.(*UDPConn).readFrom(0x10a0e100, 0x10b9fadc, 0x400, 0x400, 0x4, 0x4, 0x10da3444, 0x4)
    /usr/local/go/src/net/udpsock_posix.go:47 +0x38
net.(*UDPConn).ReadFromUDP(0x10a0e100, 0x10b9fadc, 0x400, 0x400, 0x10da3400, 0x1b8, 0x0, 0x0)
    /usr/local/go/src/net/udpsock.go:97 +0x58
projects/printer/app/ssdp.Server(0x10bdcf6c, 0x2, 0x10a9df67, 0x8)
    /home/pi/go/src/projects/printer/app/ssdp/ssdp.go:57 +0x164
created by main.afterIP
    /home/pi/printer/app/server.go:101 +0x8c

goroutine 58 [sleep]:
time.Sleep(0xf8475800, 0xd)
    /usr/local/go/src/runtime/time.go:59 +0x10c
main.updateControlPanel()
    /home/pi/printer/app/server.go:201 +0x28
created by main.afterIP
    /home/pi/printer/app/server.go:103 +0xe8

goroutine 15 [IO wait]:
net.runtime_pollWait(0x75276ca8, 0x72, 0x10b58000)
    /usr/local/go/src/runtime/netpoll.go:164 +0x44
net.(*pollDesc).wait(0x10a621bc, 0x72, 0x697c58, 0x695a00)
    /usr/local/go/src/net/fd_poll_runtime.go:75 +0x28
net.(*pollDesc).waitRead(0x10a621bc, 0x10b58000, 0x1000)
    /usr/local/go/src/net/fd_poll_runtime.go:80 +0x24
net.(*netFD).Read(0x10a62180, 0x10b58000, 0x1000, 0x1000, 0x0, 0x697c58, 0x695a00)
    /usr/local/go/src/net/fd_unix.go:250 +0x148
net.(*conn).Read(0x10a66520, 0x10b58000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/local/go/src/net/net.go:181 +0x58
net/http.(*connReader).Read(0x10a64360, 0x10b58000, 0x1000, 0x1000, 0x248f74, 0x10a62180, 0xd0f60cae)
    /usr/local/go/src/net/http/server.go:754 +0x168
bufio.(*Reader).fill(0x10ad2810)
    /usr/local/go/src/bufio/bufio.go:97 +0xf4
bufio.(*Reader).Peek(0x10ad2810, 0x4, 0xe, 0x310487d1, 0x6bf198, 0x0, 0x0)
    /usr/local/go/src/bufio/bufio.go:129 +0x58
net/http.(*conn).serve(0x10a985a0, 0x699ed8, 0x10a14160)
    /usr/local/go/src/net/http/server.go:1850 +0x7a0
created by net/http.(*Server).Serve
    /usr/local/go/src/net/http/server.go:2668 +0x234

goroutine 103 [IO wait]:
net.runtime_pollWait(0x75276d20, 0x72, 0x10c2b000)
    /usr/local/go/src/runtime/netpoll.go:164 +0x44
net.(*pollDesc).wait(0x10b333bc, 0x72, 0x697c58, 0x695a00)
    /usr/local/go/src/net/fd_poll_runtime.go:75 +0x28
net.(*pollDesc).waitRead(0x10b333bc, 0x10c2b000, 0x1000)
    /usr/local/go/src/net/fd_poll_runtime.go:80 +0x24
net.(*netFD).Read(0x10b33380, 0x10c2b000, 0x1000, 0x1000, 0x0, 0x697c58, 0x695a00)
    /usr/local/go/src/net/fd_unix.go:250 +0x148
net.(*conn).Read(0x10cafc70, 0x10c2b000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/local/go/src/net/net.go:181 +0x58
net/http.(*connReader).Read(0x10c635f0, 0x10c2b000, 0x1000, 0x1000, 0x248f74, 0x10b33380, 0xd0f60cae)
    /usr/local/go/src/net/http/server.go:754 +0x168
bufio.(*Reader).fill(0x10c63620)
    /usr/local/go/src/bufio/bufio.go:97 +0xf4
bufio.(*Reader).Peek(0x10c63620, 0x4, 0xe, 0x310a9da1, 0x6bf198, 0x0, 0x0)
    /usr/local/go/src/bufio/bufio.go:129 +0x58
net/http.(*conn).serve(0x10d5ef00, 0x699ed8, 0x10dfc340)
    /usr/local/go/src/net/http/server.go:1850 +0x7a0
created by net/http.(*Server).Serve
    /usr/local/go/src/net/http/server.go:2668 +0x234

goroutine 3664 [runnable]:
time.Sleep(0xd207f, 0x0)
    /usr/local/go/src/runtime/time.go:59 +0x10c
projects/printer/app/move.ZAxisMove(0x960, 0x1e501, 0x1fca05, 0x0, 0x1fca05, 0x0, 0x160f, 0x4b7714, 0x0, 0x0, ...)
    /home/pi/go/src/projects/printer/app/move/move.go:60 +0x4fc
main.gpioInterface(0x960, 0x6bf501, 0x12c, 0x0, 0x3b5500, 0x6bf520)
    /home/pi/printer/app/move.go:106 +0x53c
main.rise(0x960, 0x12c, 0x0, 0x6bf400, 0xf6)
    /home/pi/printer/app/move.go:59 +0x3c
main.riseMicron(0xbb8, 0x12c, 0x0, 0x0, 0x3cc5d0)
    /home/pi/printer/app/move.go:63 +0x8c
main.moveToWaitPosition()
    /home/pi/printer/app/move.go:44 +0x98
main.printLayer(0xf6, 0xf7)
    /home/pi/printer/app/printing.go:236 +0x560
main.startPlate(0x2, 0x1)
    /home/pi/printer/app/printing.go:96 +0x1a4
created by main.printerStart
    /home/pi/printer/app/web.go:660 +0x118

trap    0x0
error   0x0
oldmask 0x0
r0      0x0
r1      0x7e9
r2      0x6
r3      0x0
r4      0x76dfe094
r5      0x629ff460
r6      0x0
r7      0x10c
r8      0x1
r9      0x34
r10     0x10ec24b0
fp      0x629fec04
ip      0x629ff920
sp      0x629fead0
lr      0x76cedf44
pc      0x76cedf70
cpsr    0x20000010
fault   0x0

Last edited by juliendelnatte (2017-07-11 00:13:32)

Shahin

Administrator

Registered: 2016-02-17

Posts: 3,541

Re: Printer crashed just shy of finishing an 8h print

Are you using reliable power supply? Last couple of similar bug reports was caused by hardware issues.

juliendelnatte

Member

Registered: 2017-06-07

Posts: 84

Re: Printer crashed just shy of finishing an 8h print

I tested without any electronics, with a new power supply,... everything works great until I setup Movement GPIO's (without any electronics plugged)
I always get : "image: memory exhausted" after an hour of print +-. So I thing there is a memory bug that made Movement GPIO and 2k screen incompatibility (too much memory needed?)

Shahin

Administrator

Registered: 2016-02-17

Posts: 3,541

Re: Printer crashed just shy of finishing an 8h print

edit /boot/config.txt
And increase GPU memory share.
gpu_mem=128
See if it improve things or not.

juliendelnatte

Member

Registered: 2017-06-07

Posts: 84

Re: Printer crashed just shy of finishing an 8h print

it's already on gpu_mem=128. I'm testing with 192...

Edit : same problem for 192, I'm testing with gpu_mem=256...

Edit 2 : Still get crash with gpu_mem=256 :

runtime/cgo: pthread_create failed: Resource temporarily unavailable
SIGABRT: abort
PC=0x76c3cf70 m=70 sigcode=4294967290

goroutine 0 [idle]:

goroutine 1 [IO wait]:
net.runtime_pollWait(0x74840f78, 0x72, 0x0)
    /usr/local/go/src/runtime/netpoll.go:164 +0x44
...

What to do? I build all my resin printer around a raspberry pi and custom (home made) electronic with direct control to get the smallest and simplest configuration possible but I'm facing this last issue that prevents me to go in alpha instead of bêta version ;D (everything else : meca, electronic,... are done, tested and works really great between crashes! I really like NanoDLP and would like to make it work with my setup ;D)

Last edited by juliendelnatte (2017-07-12 13:47:45)

juliendelnatte

Member

Registered: 2017-06-07

Posts: 84

Re: Printer crashed just shy of finishing an 8h print

is it not related to the bug you get here : https://github.com/golang/go/issues/17803 ? (same error, also when moving the stepper,...)