search

google / stenographer

Stenographer is a packet capture solution which aims to quickly spool all packets to disk, then provide simple, fast access to subsets of those packets. Discussion/announcements at stenographer@googlegroups.com
Apache License 2.0
1.79k stars 238 forks source link

Crash: index out of range #167

Closed morsik closed 6 years ago

morsik commented 7 years ago

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 7 years ago

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 6 years ago

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 6 years ago

https://github.com/google/stenographer/commit/361c5cfb66a04c4fa90882b2f24d90527cc9bb2a was supposed to fix this... can you confirm whether or not it was part of your build when you saw this issue?

lungdart commented 6 years ago

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 6 years ago

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