Go AppEngine repeating partial execution of http.handler

func init() {
	http.HandleFunc("/", handler)
}

In the handler function there is code iterating over a list of data, processing it, and aggregating a results.

Lets say for a given query there are 100 items that need to be processed. For each item I write log to the Appengine console, "Item n has been processed".

Here is the problem:

The request does not return. The log message for the first 40 or so items, and then it repeats, and repeats. It always stops are the same item, and restarts.

My best guess is that the app is hitting a memory limit or something, and the Appengine Go runtime is just restarting, and re-executing the handler.

For a small list of items, processing goes as expected, and the logs don't show any looping.

There are no errors in the request log, but another log shows:

panic: poll_ctl

goroutine 3 [running]:
runtime/eventloop.(*pollServer).ctlfd(0x9035f8, 0x204100000005, 0x3, 0x2041, 0x0, ...)
	go/src/pkg/runtime/eventloop/poll_linux_amd64.go:428 +0xdf
runtime/eventloop.(*pollServer).loop(0x9035f8, 0x0)
	go/src/pkg/runtime/eventloop/poll_linux_amd64.go:411 +0x4d8
created by runtime/eventloop.init·1
	go/src/pkg/runtime/eventloop/poll_linux_amd64.go:232 +0x40

goroutine 1 [select (no cases)]:
appengine_internal/fd_transport.serveHTTP(0x7fff76502f58, 0x70615f2f00000002, 0x7fff76502f5b, 0x3, 0x7fff76502f6c, ...)
	go/src/pkg/appengine_internal/fd_transport/fd_transport.go:44 +0x26b
appengine_internal.Main()
	go/src/pkg/appengine_internal/internal.go:184 +0x1a8
main.main()
	_go_main.go:16 +0x18

goroutine 2 [select]:
created by _
	_.go:568 +0xd2

goroutine 10 [chan receive]:
runtime/eventloop.(*pollServer).wait(0x9035f8, 0xf840095a60, 0xf84011ac30, 0xb, 0x1, ...)
	go/src/pkg/runtime/eventloop/poll_linux_amd64.go:472 +0x1a7
runtime/eventloop.(*FD).ReadFrom(0xf840095a50, 0xf840138000, 0x7d0000007d0, 0xf800000000, 0x0, ...)
	go/src/pkg/runtime/eventloop/fd.go:135 +0x1c2
created by _
	_.go:144 +0x7a

goroutine 5 [chan receive]:
created by _
	_.go:461 +0x3ca

goroutine 6 [semacquire]:
sync.runtime_Semacquire(0xf8408034d8, 0xf8408034d8)
	go/src/pkg/runtime/zsema_amd64.c:146 +0x25
sync.(*Cond).Wait(0xf840096bb0, 0x1)
	go/src/pkg/sync/cond.go:67 +0xaa
created by _
	_.go:462 +0x3e1

goroutine 7 [chan receive]:
runtime/eventloop.(*pollServer).wait(0x9035f8, 0xf840095c70, 0xf84011ac30, 0xb, 0x1, ...)
	go/src/pkg/runtime/eventloop/poll_linux_amd64.go:472 +0x1a7
runtime/eventloop.(*FD).Read(0xf840095c60, 0xf84113a000, 0x972a80000000c, 0x2b5800000000, 0xf84011ac30, ...)
	go/src/pkg/runtime/eventloop/fd.go:93 +0x18c
io.ReadAtLeast(0xf84012c0c0, 0xf840095c60, 0xf84113a000, 0x972a80000000c, 0x2b580000000c, ...)
	go/src/pkg/io/io.go:254 +0xc3
io.ReadFull(0xf84012c0c0, 0xf840095c60, 0xf84113a000, 0x972a80000000c, 0xf840095c60, ...)
	go/src/pkg/io/io.go:273 +0x69
created by _
	_.go:845 +0x2c6

goroutine 11 [runnable]:
runtime/eventloop.(*pollServer).wait(0x9035f8, 0xf840095b10, 0xf84011ac30, 0xb, 0x1, ...)
	go/src/pkg/runtime/eventloop/poll_linux_amd64.go:472 +0x1a7
runtime/eventloop.(*FD).Accept(0xf840095b00, 0x0, 0x0, 0xf84011ac30, 0xb, ...)
	go/src/pkg/runtime/eventloop/fd.go:72 +0x185
net/http.(*Server).Serve(0xf840129f00, 0xf8400cfa80, 0xf840095b00, 0x0, 0x0, ...)
	go/src/pkg/net/http/server.go:1012 +0x88
net/http.Serve(0xf8400cfa80, 0xf840095b00, 0xf84012c090, 0xf8400e0b10, 0xf8400e0b10, ...)
	go/src/pkg/net/http/server.go:977 +0x71
created by _
	_.go:145 +0xe9

goroutine 12 [timer goroutine (idle)]:
created by addtimer
	go/src/pkg/runtime/ztime_amd64.c:70

goroutine 13 [runnable]:
runtime/eventloop.(*pollServer).wait(0x9035f8, 0xf8400959b0, 0xf84011ac30, 0xb, 0x1, ...)
	go/src/pkg/runtime/eventloop/poll_linux_amd64.go:472 +0x1a7
runtime/eventloop.(*FD).Read(0xf8400959a0, 0xf840139000, 0x100000001000, 0x0, 0xf84011ac30, ...)
	go/src/pkg/runtime/eventloop/fd.go:93 +0x18c
io.(*LimitedReader).Read(0xf840123580, 0xf840139000, 0x100000001000, 0xf8900000000, 0x0, ...)
	go/src/pkg/io/io.go:394 +0xc1
bufio.(*Reader).fill(0xf840129f80, 0x2b5853e92000)
	go/src/pkg/bufio/bufio.go:77 +0xf0
bufio.(*Reader).Read(0xf840129f80, 0xf84013d000, 0x27100000000c, 0xc, 0x0, ...)
	go/src/pkg/bufio/bufio.go:142 +0x188
io.ReadAtLeast(0xf84012c600, 0xf84012c570, 0xf84013d000, 0x27100000000c, 0xc, ...)
	go/src/pkg/io/io.go:254 +0xc3
io.ReadFull(0xf84012c600, 0xf84012c570, 0xf84013d000, 0x27100000000c, 0xf84012c570, ...)
	go/src/pkg/io/io.go:273 +0x69
net/http.(*conn).serve(0xf8401320c0, 0x0)
	go/src/pkg/net/http/server.go:656 +0x621
created by net/http.(*Server).Serve
	go/src/pkg/net/http/server.go:1040 +0x430

goroutine 59 [sleep]:
time.Sleep(0x5dfdee1, 0xf8408034d0)
	go/src/pkg/runtime/ztime_amd64.c:22 +0x49
created by _
	_.go:791 +0xc4

goroutine 15 [chan receive]:

Maybe I'm not logging all the errors, but even if, what could cause the looping?

Update
The near-endless-looping quickly drained my datastore write quota, now I'm getting a no-quote error, which is being logged. After the Error logs the handler is invoked again. and again....

func handleError(w http.ResponseWriter, c appengine.Context, err error) {
	c.Infof("ERROR")
	c.Errorf("ERROR datastore: %s", err.Error())
}


...
rk, err := datastore.Put(c, rk, e)
if err != nil {
	handleError(w, c, err)
	return
}

UPDATE 2
After switching to an f4 instance the code runs as expected. I still think the Appengine Go run time is silently failing for some reason, (memory), and restarting the handler execution. Thats my best guess, I have no idea.

There is a 30 second timeout for http requests. Were the processes taking that long before you moved to a faster instance? You could use a backend process to do long-lived processing. https://developers.google.com/appengine/docs/go/backends/overview