google/stenographer

Crash: index out of range

morsik opened this issue · 5 comments

morsik commented

Package: stenographer-0-1.20170718git907b3ab.el7.centos.x86_64 (built from stenographer spec file)

Backtrace:

Aug 29 11:45:37 host stenographer[121832]: panic: runtime error: index out of range
Aug 29 11:45:37 host stenographer[121832]: goroutine 82 [running]:
Aug 29 11:45:37 host stenographer[121832]: panic(0x8f6d60, 0xc82000e030)
Aug 29 11:45:37 host stenographer[121832]: /usr/lib/golang/src/runtime/panic.go:481 +0x3e6
Aug 29 11:45:37 host stenographer[121832]: github.com/google/stenographer/thread.(*Thread).pruneOldestThreadFiles(0xc82018eb40)
Aug 29 11:45:37 host stenographer[121832]: /builddir/build/BUILD/stenographer-907b3abf3e877b671e4d43bdb628948feaee2c22/src/github.com/google/stenographer/thread/thread.go:234 +0x3c2
Aug 29 11:45:37 host stenographer[121832]: github.com/google/stenographer/thread.(*Thread).cleanUpOnLowDiskSpace(0xc82018eb40)
Aug 29 11:45:37 host stenographer[121832]: /builddir/build/BUILD/stenographer-907b3abf3e877b671e4d43bdb628948feaee2c22/src/github.com/google/stenographer/thread/thread.go:206 +0xa44

Config:

{
  "Threads": [
      { "PacketsDirectory": "/data/1", "IndexDirectory": "/index/1", "DiskFreePercentage": 50}
    , { "PacketsDirectory": "/data/2", "IndexDirectory": "/index/2", "DiskFreePercentage": 50}
    , { "PacketsDirectory": "/data/3", "IndexDirectory": "/index/3", "DiskFreePercentage": 50}
    , { "PacketsDirectory": "/data/4", "IndexDirectory": "/index/4", "DiskFreePercentage": 50}
    , { "PacketsDirectory": "/data/5", "IndexDirectory": "/index/5", "DiskFreePercentage": 50}
    , { "PacketsDirectory": "/data/6", "IndexDirectory": "/index/6", "DiskFreePercentage": 50}
    , { "PacketsDirectory": "/data/7", "IndexDirectory": "/index/7", "DiskFreePercentage": 50}
    , { "PacketsDirectory": "/data/8", "IndexDirectory": "/index/8", "DiskFreePercentage": 50}
    , { "PacketsDirectory": "/data/9", "IndexDirectory": "/index/9", "DiskFreePercentage": 50}
    , { "PacketsDirectory": "/data/10", "IndexDirectory": "/index/10", "DiskFreePercentage": 50}
    , { "PacketsDirectory": "/data/11", "IndexDirectory": "/index/11", "DiskFreePercentage": 50}
    , { "PacketsDirectory": "/data/12", "IndexDirectory": "/index/12", "DiskFreePercentage": 50}
    , { "PacketsDirectory": "/data/13", "IndexDirectory": "/index/13", "DiskFreePercentage": 50}
    , { "PacketsDirectory": "/data/14", "IndexDirectory": "/index/14", "DiskFreePercentage": 50}
    , { "PacketsDirectory": "/data/15", "IndexDirectory": "/index/15", "DiskFreePercentage": 50}
    , { "PacketsDirectory": "/data/16", "IndexDirectory": "/index/16", "DiskFreePercentage": 50}
    , { "PacketsDirectory": "/data/17", "IndexDirectory": "/index/17", "DiskFreePercentage": 50}
    , { "PacketsDirectory": "/data/18", "IndexDirectory": "/index/18", "DiskFreePercentage": 50}
  ]
  , "StenotypePath": "/usr/bin/stenotype"
  , "Interface": "bond0"
  , "Port": 1234
  , "Host": "127.0.0.1"
  , "Flags": []
  , "CertPath": "/etc/stenographer/certs"
}
morsik commented

And another right on cleaning after few minutes of working:

Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Thread 12 disk usage is high (packet path="/tmp/stenographer078694849/PKT12"): 49% free <= 50% threshold
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Thread 12 deleting 1 files to free up 1132462080 bytes.
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Thread 12 removing "1504004501730743"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Thread 12 untracking "1504004501730743"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Thread 12 old blockfile "/tmp/stenographer078694849/PKT12/1504004501730743"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Blockfile closing: "/tmp/stenographer078694849/PKT12/1504004501730743"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Deleting "/tmp/stenographer078694849/PKT12/1504004501730743"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Closing "/tmp/stenographer078694849/IDX12/1504004501730743"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Closing "/tmp/stenographer078694849/PKT12/1504004501730743"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Deleting "/tmp/stenographer078694849/IDX12/1504004501730743"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Thread 12 disk usage is high (packet path="/tmp/stenographer078694849/PKT12"): 49% free <= 50% threshold
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Thread 12 deleting 2 files to free up 2209349632 bytes.
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Thread 12 removing "1504004562736642"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Thread 12 removing "1504004623781895"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Thread 12 untracking "1504004562736642"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Deleting "/tmp/stenographer078694849/IDX12/1504004562736642"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Deleting "/tmp/stenographer078694849/PKT12/1504004623781895"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Thread 12 old blockfile "/tmp/stenographer078694849/PKT12/1504004562736642"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Blockfile closing: "/tmp/stenographer078694849/PKT12/1504004562736642"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Closing "/tmp/stenographer078694849/IDX12/1504004562736642"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Closing "/tmp/stenographer078694849/PKT12/1504004562736642"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Thread 12 untracking "1504004623781895"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Thread 12 old blockfile "/tmp/stenographer078694849/PKT12/1504004623781895"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Blockfile closing: "/tmp/stenographer078694849/PKT12/1504004623781895"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Closing "/tmp/stenographer078694849/IDX12/1504004623781895"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Closing "/tmp/stenographer078694849/PKT12/1504004623781895"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Deleting "/tmp/stenographer078694849/IDX12/1504004623781895"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Deleting "/tmp/stenographer078694849/PKT12/1504004562736642"
Aug 29 13:10:24 host stenographer[141986]: 2017/08/29 13:10:24 Thread 12 disk usage is high (packet path="/tmp/stenographer078694849/PKT12"): 49% free <= 50% threshold
Aug 29 13:10:24 host stenographer[141986]: panic: runtime error: index out of range
Aug 29 13:10:24 host stenographer[141986]: goroutine 91 [running]:
Aug 29 13:10:24 host stenographer[141986]: panic(0x8f6d60, 0xc82000e030)
Aug 29 13:10:24 host stenographer[141986]: /usr/lib/golang/src/runtime/panic.go:481 +0x3e6
Ulrhol commented

I experience the same.

2018/01/15 01:43:38 Thread 0 disk usage is high (packet path="/tmp/stenographer162108831/PKT0"): 20% free <= 20% threshold
panic: runtime error: index out of range

goroutine 7 [running]:
panic(0x8f6d60, 0xc820010020)
        /usr/lib/golang/src/runtime/panic.go:481 +0x3e6
github.com/google/stenographer/thread.(*Thread).pruneOldestThreadFiles(0xc820129540)
        /builddir/build/BUILD/stenographer-844b5a4e538b4a560550b227c28ac911833713dd/src/github.com/google/stenographer/thread/thread.go:229 +0x3c9
github.com/google/stenographer/thread.(*Thread).cleanUpOnLowDiskSpace(0xc820129540)
        /builddir/build/BUILD/stenographer-844b5a4e538b4a560550b227c28ac911833713dd/src/github.com/google/stenographer/thread/thread.go:206 +0xa44
github.com/google/stenographer/thread.(*Thread).SyncFiles(0xc820129540)
        /builddir/build/BUILD/stenographer-844b5a4e538b4a560550b227c28ac911833713dd/src/github.com/google/stenographer/thread/thread.go:353 +0x49
github.com/google/stenographer/env.(*Env).syncFiles(0xc821188750)
        /builddir/build/BUILD/stenographer-844b5a4e538b4a560550b227c28ac911833713dd/src/github.com/google/stenographer/env/env.go:260 +0x70
github.com/google/stenographer/env.(*Env).(github.com/google/stenographer/env.syncFiles)-fm()
        /builddir/build/BUILD/stenographer-844b5a4e538b4a560550b227c28ac911833713dd/src/github.com/google/stenographer/env/env.go:131 +0x20
github.com/google/stenographer/env.(*Env).callEvery(0xc821188750, 0xc82117e430, 0x37e11d600)
        /builddir/build/BUILD/stenographer-844b5a4e538b4a560550b227c28ac911833713dd/src/github.com/google/stenographer/env/env.go:179 +0x12f
created by github.com/google/stenographer/env.New
        /builddir/build/BUILD/stenographer-844b5a4e538b4a560550b227c28ac911833713dd/src/github.com/google/stenographer/env/env.go:131 +0x50f
gconnell commented

361c5cf was supposed to fix this... can you confirm whether or not it was part of your build when you saw this issue?

lungdart commented

Same experience here


goroutine 6 [running]:
panic(0x90c4e0, 0xc82000a0d0)
	/usr/lib/go-1.6/src/runtime/panic.go:481 +0x3e6
github.com/google/stenographer/thread.(*Thread).pruneOldestThreadFiles(0xc820183680)
	/home/shawn/go/src/github.com/google/stenographer/thread/thread.go:237 +0x3d3
github.com/google/stenographer/thread.(*Thread).cleanUpOnLowDiskSpace(0xc820183680)
	/home/shawn/go/src/github.com/google/stenographer/thread/thread.go:206 +0xa44
github.com/google/stenographer/thread.(*Thread).SyncFiles(0xc820183680)
	/home/shawn/go/src/github.com/google/stenographer/thread/thread.go:356 +0x49
github.com/google/stenographer/env.(*Env).syncFiles(0xc8201def70)
	/home/shawn/go/src/github.com/google/stenographer/env/env.go:260 +0x70
github.com/google/stenographer/env.(*Env).(github.com/google/stenographer/env.syncFiles)-fm()
	/home/shawn/go/src/github.com/google/stenographer/env/env.go:131 +0x20
github.com/google/stenographer/env.(*Env).callEvery(0xc8201def70, 0xc82000b520, 0x37e11d600)
	/home/shawn/go/src/github.com/google/stenographer/env/env.go:179 +0x12f
created by github.com/google/stenographer/env.New
	/home/shawn/go/src/github.com/google/stenographer/env/env.go:131 +0x50f

And I can confirm my build contains that patch. Built on Ubuntu 16.04.03 Server using the install scripts, run manually as stenographer without upstart scripts.

Here is my configuration:

{
  "Threads": [
    {
      "PacketsDirectory": "/stenographer/pkt/0",
      "IndexDirectory": "/stenographer/idx/0",
      "MaxDirectoryFiles": 30000,
      "DiskFreePercentage": 10
    },
    {
      "PacketsDirectory": "/stenographer/pkt/1",
      "IndexDirectory": "/stenographer/idx/1",
      "MaxDirectoryFiles": 30000,
      "DiskFreePercentage": 10
    },
    {
      "PacketsDirectory": "/stenographer/pkt/2",
      "IndexDirectory": "/stenographer/idx/2",
      "MaxDirectoryFiles": 30000,
      "DiskFreePercentage": 10
    },
    {
      "PacketsDirectory": "/stenographer/pkt/3",
      "IndexDirectory": "/stenographer/idx/3",
      "MaxDirectoryFiles": 30000,
      "DiskFreePercentage": 10
    },
    {
      "PacketsDirectory": "/stenographer/pkt/4",
      "IndexDirectory": "/stenographer/idx/4",
      "MaxDirectoryFiles": 30000,
      "DiskFreePercentage": 10
    },
    {
      "PacketsDirectory": "/stenographer/pkt/5",
      "IndexDirectory": "/stenographer/idx/5",
      "MaxDirectoryFiles": 30000,
      "DiskFreePercentage": 10
    }
  ],
  "StenotypePath": "/usr/bin/stenotype",
  "Interface": "enp4s0f1",
  "Port": 1234,
  "Host": "127.0.0.1",
  "Flags": ["-v"],
  "CertPath": "/etc/stenographer/certs"
}

And my filesystem layout (All filesystems are ext4):

udev            7.9G     0  7.9G   0% /dev
tmpfs           1.6G   86M  1.5G   6% /run
/dev/sdu1       902G  2.1G  854G   1% /
tmpfs           7.9G     0  7.9G   0% /dev/shm
tmpfs           5.0M     0  5.0M   0% /run/lock
tmpfs           7.9G     0  7.9G   0% /sys/fs/cgroup
tmpfs           1.6G     0  1.6G   0% /run/user/1000
/dev/sda1       917G  766G  106G  88% /stenographer/pkt/0
/dev/sdb1       917G  768G  103G  89% /stenographer/pkt/1
/dev/sdc1       917G  5.6G  865G   1% /stenographer/pkt/2
/dev/sdd1       917G  769G  102G  89% /stenographer/pkt/3
/dev/sde1       1.8T  832G  910G  48% /stenographer/pkt/4
/dev/sdf1       1.8T  862G  880G  50% /stenographer/pkt/5
/dev/sdn1       917G   60G  812G   7% /stenographer/idx
gconnell commented

Thanks to aeppert for finding/fixing the actual cause of this!