API returns HTTP status 500 after a few days

[gunnarbeutner]

After a few days of running just fine I'm getting HTTP status code 500 when trying to update a repository:

acheron:~ gunnar$ curl -v -k -u 'icinga:xxx' -X POST https://icinga-aptly.icinga.netways.de/api/repos/icinga-ubuntu-xenial-snapshot/file/icinga2-ubuntu-xenial-x86_64-snapshot
*   Trying 10.10.27.25...
* Connected to icinga-aptly.icinga.netways.de (10.10.27.25) port 443 (#0)
* ALPN, offering http/1.1
* Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
* successfully set certificate verify locations:
*   CAfile: /opt/local/share/curl/curl-ca-bundle.crt
  CApath: none
* TLSv1.2 (OUT), TLS header, Certificate Status (22):
* TLSv1.2 (OUT), TLS handshake, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Client hello (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS change cipher, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES256-GCM-SHA384
* ALPN, server did not agree to a protocol
* Server certificate:
*  subject: OU=Domain Control Validated; OU=PositiveSSL Wildcard; CN=*.icinga.org
*  start date: Apr 28 00:00:00 2015 GMT
*  expire date: Jul 26 23:59:59 2018 GMT
*  issuer: C=GB; ST=Greater Manchester; L=Salford; O=COMODO CA Limited; CN=COMODO RSA Domain Validation Secure Server CA
*  SSL certificate verify ok.
* Server auth using Basic with user 'icinga'
> POST /api/repos/icinga-ubuntu-xenial-snapshot/file/icinga2-ubuntu-xenial-x86_64-snapshot HTTP/1.1
> Host: icinga-aptly.icinga.netways.de
> Authorization: Basic xxx
> User-Agent: curl/7.50.0
> Accept: */*
>
< HTTP/1.1 500 Internal Server Error
< Date: Mon, 08 Aug 2016 06:34:22 GMT
< Server: Apache/2.4.10 (Debian)
< Content-Length: 0
< Content-Type: text/plain; charset=utf-8
< Connection: close
<
* Closing connection 0
* TLSv1.2 (OUT), TLS alert, Client hello (1):

While trying to analyze the problem I've noticed that the thread that's used to handle the request is getting a SEGV signal:

549   read(10, "POST /api/repos/icinga-ubuntu-xenial-snapshot/file/icinga2-ubuntu-xenial-x86_64-snapshot HTTP/1.1\r\nHost: icinga-aptly.icinga.netways.de\r\nAuthorization: Basic xxxx\r\nUser-Agent: curl/7.47.0\r\nAccept: */*\r\nX-Forwarded-For: 10.10.27.34\r\nX-Forwarded-Host: icinga-aptly.icinga.netways.de\r\nX-Forwarded-Server: icinga-aptly.icinga.netways.de\r\nConnection: Keep-Alive\r\n\r\n", 4096) = 384
549   clock_gettime(CLOCK_REALTIME, {1470637492, 452563917}) = 0
549   --- SIGSEGV {si_signo=SIGSEGV, si_code=SEGV_MAPERR, si_addr=0} ---

Here's a stacktrace for that signal:

Program received signal SIGSEGV, Segmentation fault.
0x00000000007813a1 in github.com/syndtr/goleveldb/leveldb.(*DB).isClosed (db=0x0, ~r0=240) at /Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/syndtr/goleveldb/leveldb/db_state.go:210
210 /Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/syndtr/goleveldb/leveldb/db_state.go: No such file or directory.
(gdb) bt
#0  0x00000000007813a1 in github.com/syndtr/goleveldb/leveldb.(*DB).isClosed (db=0x0, ~r0=240) at /Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/syndtr/goleveldb/leveldb/db_state.go:210
#1  0x00000000007813ed in github.com/syndtr/goleveldb/leveldb.(*DB).ok (db=0x0, ~r0=...) at /Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/syndtr/goleveldb/leveldb/db_state.go:215
#2  0x00000000007712f2 in github.com/syndtr/goleveldb/leveldb.(*DB).NewIterator (db=0x0, slice=0x0, ro=0x0, ~r2=...) at /Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/syndtr/goleveldb/leveldb/db.go:874
#3  0x00000000005d6a69 in github.com/smira/aptly/database.(*levelDB).FetchByPrefix (l=0xc820044940, prefix=..., ~r1=...) at /Users/smira/Documents/go/src/github.com/smira/aptly/database/leveldb.go:142
#4  0x0000000000533fc4 in github.com/smira/aptly/deb.NewLocalRepoCollection (db=..., ~r1=0xc82019ae20) at /Users/smira/Documents/go/src/github.com/smira/aptly/deb/local.go:106
#5  0x000000000051edf4 in github.com/smira/aptly/deb.(*CollectionFactory).LocalRepoCollection (factory=0xc8201a1740, ~r0=0x0) at /Users/smira/Documents/go/src/github.com/smira/aptly/deb/collections.go:66
#6  0x00000000004ca2e1 in github.com/smira/aptly/api.apiReposPackageFromDir (c=0xc8201d22c0) at /Users/smira/Documents/go/src/github.com/smira/aptly/api/repos.go:282
#7  0x000000000067a07f in github.com/gin-gonic/gin.(*Context).Next (c=0xc8201d22c0) at /Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/context.go:114
#8  0x00000000004d1034 in github.com/smira/aptly/api.Router.func1 (c=0xc8201d22c0) at /Users/smira/Documents/go/src/github.com/smira/aptly/api/router.go:43
#9  0x000000000067a07f in github.com/gin-gonic/gin.(*Context).Next (c=0xc8201d22c0) at /Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/context.go:114
#10 0x000000000068257c in github.com/gin-gonic/gin.ErrorLoggerT.func1 (c=0xc8201d22c0) at /Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/logger.go:30
#11 0x000000000067a07f in github.com/gin-gonic/gin.(*Context).Next (c=0xc8201d22c0) at /Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/context.go:114
#12 0x00000000006826c5 in github.com/gin-gonic/gin.Logger.func1 (c=0xc8201d22c0) at /Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/logger.go:49
#13 0x000000000067a07f in github.com/gin-gonic/gin.(*Context).Next (c=0xc8201d22c0) at /Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/context.go:114
#14 0x00000000006831a8 in github.com/gin-gonic/gin.Recovery.func1 (c=0xc8201d22c0) at /Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/recovery.go:96
#15 0x000000000067a07f in github.com/gin-gonic/gin.(*Context).Next (c=0xc8201d22c0) at /Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/context.go:114
#16 0x0000000000683280 in github.com/gin-gonic/gin.(*RouterGroup).Handle.func1 (w=..., req=0xc821507960, params=...) at /Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/routergroup.go:57
#17 0x00000000007c23fd in github.com/julienschmidt/httprouter.(*Router).ServeHTTP (r=0xc82000d3c0, w=..., req=0xc821507960) at /Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/julienschmidt/httprouter/router.go:276
#18 0x000000000067de53 in github.com/gin-gonic/gin.(*Engine).ServeHTTP (engine=0xc820172300, writer=..., request=0xc821507960) at /Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/gin.go:126
#19 0x00000000004f682e in net/http.serverHandler.ServeHTTP (sh=..., rw=..., req=0xc821507960) at /usr/local/Cellar/go/1.5.3/libexec/src/net/http/server.go:1862
#20 0x00000000004f3ede in net/http.(*conn).serve (c=0xc8201d24d0) at /usr/local/Cellar/go/1.5.3/libexec/src/net/http/server.go:1361
#21 0x000000000045c181 in runtime.goexit () at /usr/local/Cellar/go/1.5.3/libexec/src/runtime/asm_amd64.s:1721
#22 0x000000c8201d24d0 in ?? ()
#23 0x0000000000000000 in ?? ()

I've been unable to easily reproduce this issue. It just tends to start happening after a few days. However, once it does happen all further POST requests for repos will fail in the same manner.

[chrillux]

I'm experiencing the same problems. I'm using Aptly 0.9.7 on Ubuntu Xenial. The problem showed up after a few days. It was still possible to go to the version endpoint, /api/version. Things that did not work was e.g /api/publish or /api/snapshots.

<... accept4 resumed> {sa_family=AF_INET, sin_port=htons(55710), sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_CLOEXEC|SOCK_NONBLOCK) = 5
read(5, "GET /api/snapshots HTTP/1.1\r\nHost: 127.0.0.1\r\nUser-Agent: curl/7.47.0\r\nAccept: */*\r\n\r\n", 4096) = 86
openat(AT_FDCWD, "/usr/local/Cellar/go/1.5.3/libexec/src/runtime/panic.go", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/local/Cellar/go/1.5.3/libexec/src/runtime/panic.go", O_RDONLY|O_CLOEXEC <unfinished ...>
openat(AT_FDCWD, "/usr/local/Cellar/go/1.5.3/libexec/src/runtime/sigpanic_unix.go", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/syndtr/goleveldb/leveldb/db_state.go", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/syndtr/goleveldb/leveldb/db_state.go", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/syndtr/goleveldb/leveldb/db.go", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/Users/smira/Documents/go/src/github.com/smira/aptly/database/leveldb.go", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/Users/smira/Documents/go/src/github.com/smira/aptly/deb/snapshot.go", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/Users/smira/Documents/go/src/github.com/smira/aptly/deb/collections.go", O_RDONLY|O_CLOEXEC <unfinished ...>
openat(AT_FDCWD, "/Users/smira/Documents/go/src/github.com/smira/aptly/api/snapshot.go", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/context.go", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/Users/smira/Documents/go/src/github.com/smira/aptly/api/router.go", O_RDONLY|O_CLOEXEC <unfinished ...>
openat(AT_FDCWD, "/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/context.go", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/logger.go", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/context.go", O_RDONLY|O_CLOEXEC <unfinished ...>
openat(AT_FDCWD, "/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/logger.go", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/context.go", O_RDONLY|O_CLOEXEC <unfinished ...>
openat(AT_FDCWD, "/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/recovery.go", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/context.go", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/routergroup.go", O_RDONLY|O_CLOEXEC <unfinished ...>
openat(AT_FDCWD, "/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/julienschmidt/httprouter/router.go", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/gin.go", O_RDONLY|O_CLOEXEC <unfinished ...>
openat(AT_FDCWD, "/usr/local/Cellar/go/1.5.3/libexec/src/net/http/server.go", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/local/Cellar/go/1.5.3/libexec/src/net/http/server.go", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/local/Cellar/go/1.5.3/libexec/src/runtime/asm_amd64.s", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
write(2, "2017/03/21 08:40:00 PANIC: runtime error: invalid memory address or nil pointer dereference\n/usr/local/Cellar/go/1.5.3/libexec/src/runtime/panic.go:423 (0x4296b9)\n/usr/local/Cellar/go/1.5.3/libexec/src/runtime/panic.go:42 (0x427d79)\n/usr/local/Cellar/go/1.5.3/libexec/src/runtime/sigpanic_unix.go:24 (0x43e7fa)\n/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/syndtr/goleveldb/leveldb/db_state.go:210 (0x7813a1)\n/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/syndtr/goleveldb/leveldb/db_state.go:215 (0x7813ed)\n/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/syndtr/goleveldb/leveldb/db.go:874 (0x7712f2)\n/Users/smira/Documents/go/src/github.com/smira/aptly/database/leveldb.go:142 (0x5d6a69)\n/Users/smira/Documents/go/src/github.com/smira/aptly/deb/snapshot.go:177 (0x561e04)\n/Users/smira/Documents/go/src/github.com/smira/aptly/deb/collections.go:54 (0x51ed04)\n/Users/smira/Documents/go/src/github.com/smira/aptly/api/snapshot.go:14 (0x4cda96)\n/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/context.go:114 (0x67a07f)\n/Users/smira/Documents/go/src/github.com/smira/aptly/api/router.go:43 (0x4d1034)\n/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/context.go:114 (0x67a07f)\n/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/logger.go:30 (0x68257c)\n/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/context.go:114 (0x67a07f)\n/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/logger.go:49 (0x6826c5)\n/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/context.go:114 (0x67a07f)\n/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/recovery.go:96 (0x6831a8)\n/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/context.go:114 (0x67a07f)\n/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/routergroup.go:57 (0x683280)\n/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/julienschmidt/httprouter/router.go:276 (0x7c23fd)\n/Users/smira/Documents/go/src/github.com/smira/aptly/_vendor/src/github.com/gin-gonic/gin/gin.go:126 (0x67de53)\n/usr/local/Cellar/go/1.5.3/libexec/src/net/http/server.go:1862 (0x4f682e)\n/usr/local/Cellar/go/1.5.3/libexec/src/net/http/server.go:1361 (0x4f3ede)\n/usr/local/Cellar/go/1.5.3/libexec/src/runtime/asm_amd64.s:1721 (0x45c181)\n", 2615) = 2615
write(5, "HTTP/1.1 500 Internal Server Error\r\nDate: Tue, 21 Mar 2017 07:40:00 GMT\r\nContent-Length: 0\r\nContent-Type: text/plain; charset=utf-8\r\n\r\n", 135 <unfinished ...>

Any progress or ideas about this?

[gunnarbeutner]

We're still seeing the same problem here and have resorted to just restarting aptly whenever /api/publish requests fail. It's far from ideal but that's the only reasonable thing we managed to come up with, short of learning Go and debugging this ourselves. :)

[smira]

I wonder if that got fixed in the latest nightly build (https://www.aptly.info/download/).

We have bumped goleveldb version since then.

[GeorgeKT]

We are also experiencing this problem with version 1.0.1:

2017/05/15 08:49:15 PANIC: runtime error: invalid memory address or nil pointer dereference
/usr/local/Cellar/go/1.8/libexec/src/runtime/panic.go:489 (0x42877f)
/usr/local/Cellar/go/1.8/libexec/src/runtime/panic.go:63 (0x42762e)
/usr/local/Cellar/go/1.8/libexec/src/runtime/signal_unix.go:290 (0x43da7f)
/Users/smira/Documents/go/src/github.com/smira/aptly/vendor/github.com/syndtr/goleveldb/leveldb/db_state.go:230 (0x7748b5)
/Users/smira/Documents/go/src/github.com/smira/aptly/vendor/github.com/syndtr/goleveldb/leveldb/db_state.go:235 (0x7748fb)
/Users/smira/Documents/go/src/github.com/smira/aptly/vendor/github.com/syndtr/goleveldb/leveldb/db.go:876 (0x767357)
/Users/smira/Documents/go/src/github.com/smira/aptly/database/leveldb.go:172 (0x79426a)
/Users/smira/Documents/go/src/github.com/smira/aptly/deb/local.go:107 (0x8b8f1a)
/Users/smira/Documents/go/src/github.com/smira/aptly/deb/collections.go:74 (0x8a7091)
/Users/smira/Documents/go/src/github.com/smira/aptly/api/repos.go:104 (0xa6711f)
/Users/smira/Documents/go/src/github.com/smira/aptly/vendor/github.com/gin-gonic/gin/context.go:114 (0x72e77d)
/Users/smira/Documents/go/src/github.com/smira/aptly/api/router.go:44 (0xa6dad1)
/Users/smira/Documents/go/src/github.com/smira/aptly/vendor/github.com/gin-gonic/gin/context.go:114 (0x72e77d)
/Users/smira/Documents/go/src/github.com/smira/aptly/vendor/github.com/gin-gonic/gin/logger.go:30 (0x734ab6)
/Users/smira/Documents/go/src/github.com/smira/aptly/vendor/github.com/gin-gonic/gin/context.go:114 (0x72e77d)
/Users/smira/Documents/go/src/github.com/smira/aptly/vendor/github.com/gin-gonic/gin/logger.go:49 (0x734bc2)
/Users/smira/Documents/go/src/github.com/smira/aptly/vendor/github.com/gin-gonic/gin/context.go:114 (0x72e77d)
/Users/smira/Documents/go/src/github.com/smira/aptly/vendor/github.com/gin-gonic/gin/recovery.go:96 (0x735571)
/Users/smira/Documents/go/src/github.com/smira/aptly/vendor/github.com/gin-gonic/gin/context.go:114 (0x72e77d)
/Users/smira/Documents/go/src/github.com/smira/aptly/vendor/github.com/gin-gonic/gin/routergroup.go:57 (0x735650)
/Users/smira/Documents/go/src/github.com/smira/aptly/vendor/github.com/julienschmidt/httprouter/router.go:299 (0x72a3d0)
/Users/smira/Documents/go/src/github.com/smira/aptly/vendor/github.com/gin-gonic/gin/gin.go:126 (0x7316dd)
/usr/local/Cellar/go/1.8/libexec/src/net/http/server.go:2568 (0x6c8282)
/usr/local/Cellar/go/1.8/libexec/src/net/http/server.go:1825 (0x6c4482)
/usr/local/Cellar/go/1.8/libexec/src/runtime/asm_amd64.s:2197 (0x4552d1)

[smira]

Looks like some kind of a race here, I'll take a look. Thanks for reporting it!