DRP 4.2.0 crash report

[mclamb]

dr-provision2020/01/26 21:53:08.507977 Version: v4.2.0

I have had drp crash a few time over the past week or so while doing some non-standard mucking around with machine runners. I cannot say exactly what causes the behavior as I do not have a deterministic recreation, but I have been stopping and starting drpcli machines processjobs a lot lately, running both on host and within docker containers. I am also doing some forced job manipulation (e.g. forcing the current job status to be set to "finished" via drpcli within the task itself) so maybe that could have something to do with it.

Crash logs:

608 dr-provision2020/01/25 20:39:02.844858 [5905:290]:manager [error]: /home/travis/gopath/src/github.com/rackn/provision-plugins/cmds/manager/endpoint-actions.go:462
609 [5905:290]0e:01:00:10:00:02: Queuing Update (endpoint-actions.go:678 - Event (contents.update)):·
610 dr-provision2020/01/25 20:42:29.021363 [46500:291]:frontend [audit]: /home/travis/gopath/src/github.com/rackn/provision-server/frontend/frontend.go:383
611 [46500:291]Authenticated user rocketskates from 172.17.0.1
612 dr-provision2020/01/25 20:42:39.473133 [5972:292]:manager [error]: /home/travis/gopath/src/github.com/rackn/provision-plugins/cmds/manager/endpoint-actions.go:462
613 [5972:292]0e:01:00:10:00:02: Queuing Update (endpoint-actions.go:678 - Event (contents.update)):·
614 dr-provision2020/01/25 20:55:19.443512 [46915:293]:frontend [audit]: /home/travis/gopath/src/github.com/rackn/provision-server/frontend/frontend.go:383
615 [46915:293]Authenticated user rocketskates from 172.17.0.1
616 dr-provision2020/01/25 20:55:29.545223 [6021:294]:manager [error]: /home/travis/gopath/src/github.com/rackn/provision-plugins/cmds/manager/endpoint-actions.go:462
617 [6021:294]0e:01:00:10:00:02: Queuing Update (endpoint-actions.go:678 - Event (contents.update)):·
618 2020/01/25 20:56:11 unblockRunnable did not find anything to unblock!
619 2020/01/25 20:56:11 Running: 0, unblocked: 0, total: 2
620 2020/01/25 20:56:11 Dumping transaction locks:
621 2020/01/25 20:56:11 tx 45087: abort: false, wantWrite: true
622 2020/01/25 20:56:11 owned: map[jobs:0b3350a8-7fa6-4312-9715-50436e214db8:true jobs:5b91efe4-6530-4f0b-8119-d96626763c9c:true machines:251b3805-4598-4f7c-9767-54134f4aa505:fal ↪\se stages:discover:false tasks:enforce-sledgehammer:false]
623 2020/01/25 20:56:11 wanted: [machines:251b3805-4598-4f7c-9767-54134f4aa505]
624 2020/01/25 20:56:11 tx 45089: abort: false, wantWrite: false
625 2020/01/25 20:56:11 owned: map[machines:251b3805-4598-4f7c-9767-54134f4aa505:false]
626 2020/01/25 20:56:11 wanted: [jobs:0b3350a8-7fa6-4312-9715-50436e214db8]
627 panic: unblockRunnable did not unblock anything! [recovered]
628 │▸▸▸panic: unblockRunnable did not unblock anything!
629
630 goroutine 367978 [running]:
631 github.com/rackn/provision-server/v4/backend.(*RequestTracker).do.func1(0xc024f259a0)
632 │▸▸▸/home/travis/gopath/src/github.com/rackn/provision-server/backend/requestTracker.go:394 +0x7b
633 panic(0xec2ee0, 0x11f7680)
634 │▸▸▸/home/travis/.gimme/versions/go1.13.linux.amd64/src/runtime/panic.go:679 +0x1b2
635 github.com/rackn/provision-server/v4/backend.(*txInterlockTracker).unblockRunnable(0x4c508e0)
636 │▸▸▸/home/travis/gopath/src/github.com/rackn/provision-server/backend/tx.go:200 +0x64b
637 github.com/rackn/provision-server/v4/backend.(*txInterlockTracker).release(0x4c508e0, 0xb025)
638 │▸▸▸/home/travis/gopath/src/github.com/rackn/provision-server/backend/tx.go:214 +0x205
639 github.com/rackn/provision-server/v4/backend.(*RequestTracker).unlocker(0xc00b396840, 0xbf8348bac65d8872, 0xa083f2f322dd, 0x4c63d20, 0xc024f25970)
640 │▸▸▸/home/travis/gopath/src/github.com/rackn/provision-server/backend/requestTracker.go:122 +0x576
641 github.com/rackn/provision-server/v4/backend.(*RequestTracker).do(0xc00b396840, 0xc0074dea00, 0x44a300)
642 │▸▸▸/home/travis/gopath/src/github.com/rackn/provision-server/backend/requestTracker.go:419 +0x2e8
643 github.com/rackn/provision-server/v4/backend.(*RequestTracker).Do(0xc00b396840, 0xc024f25a00)
644 │▸▸▸/home/travis/gopath/src/github.com/rackn/provision-server/backend/requestTracker.go:428 +0x54
645 github.com/rackn/provision-server/v4/backend.FindLease(0xc00b396840, 0x107b213, 0x3, 0xc00f2947e0, 0x11, 0xc00311050c, 0x4, 0x11a, 0xc015162b20, 0x1, ...)
646 │▸▸▸/home/travis/gopath/src/github.com/rackn/provision-server/backend/dhcpUtils.go:275 +0x1c6
647 github.com/rackn/provision-server/v4/midlayer.(*DhcpRequest).ServeDHCP(0xc00ecb6780, 0xc0029457d0, 0x16)
648 │▸▸▸/home/travis/gopath/src/github.com/rackn/provision-server/midlayer/dhcp.go:581 +0x1fe0
649 github.com/rackn/provision-server/v4/midlayer.(*DhcpRequest).Process(0xc00ecb6780, 0xc00c61e370, 0xc002952fa8, 0x6fc6eb, 0x4c83238)
650 │▸▸▸/home/travis/gopath/src/github.com/rackn/provision-server/midlayer/dhcp.go:791 +0x8ec
651 github.com/rackn/provision-server/v4/midlayer.(*DhcpRequest).Run(0xc00ecb6780, 0x126)
652 │▸▸▸/home/travis/gopath/src/github.com/rackn/provision-server/midlayer/dhcp.go:816 +0x40
653 created by github.com/rackn/provision-server/v4/midlayer.(*DhcpHandler).Serve
654 │▸▸▸/home/travis/gopath/src/github.com/rackn/provision-server/midlayer/dhcp.go:888 +0x379
NORMAL ~/drp/drp.log unix | utf-8 | log 96% 631:5

[VictorLowther]

OK, found the root cause -- it was a corner case in the transaction logic. The next sets of releases will have a fix.