search

kahing / goofys

a high-performance, POSIX-ish Amazon S3 file system written in Go
Apache License 2.0
5.22k stars 522 forks source link

index out of range panic. #193

Closed brentp closed 7 years ago

brentp commented 7 years ago

I have some long running processing that are (ab)using goofys with a lot of seeks followed by reads. I ran with both debug flags and at the end of megabytes of output is the traceback below. this is with v0.0.12. Let me know if you need the full output. I'm pulling from cloudwatch logs so it's easier to get the tail.

2017/06/19 18:28:58.654265 fuse.DEBUG Op 0x00012145 connection.go:479] -> OK ()
2017/06/19 18:28:58.654184 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.654830 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4690632704 65536]
2017/06/19 18:28:58.654848 fuse.DEBUG out of order read 78 sarcoma/764-SS-767/764-SS-767.bam [4690632704 4690890752]
panic: runtime error: index out of range
goroutine 133887 [running]:
github.com/kahing/goofys/internal.(*MBuf).WriteFrom(0xc43ec47000, 0x7f0c7baab8f8, 0xc43c2ca980, 0x7f0c7baab8f8, 0xc43c2ca980, 0x1)
created by github.com/kahing/goofys/internal.Buffer.Init
/home/khc/Code/go/src/github.com/kahing/goofys/internal/buffer_pool.go:312 +0xff
/home/khc/Code/go/src/github.com/kahing/goofys/internal/buffer_pool.go:264 +0x1ce
github.com/kahing/goofys/internal.Buffer.Init.func1(0xc43ec47040, 0xc48c2c0e40)
/home/khc/Code/go/src/github.com/kahing/goofys/internal/buffer_pool.go:311 +0x35
/home/khc/Code/go/src/github.com/kahing/goofys/internal/buffer_pool.go:334 +0x99
github.com/kahing/goofys/internal.(*Buffer).readLoop(0xc43ec47040, 0xc48c2c0e40)
github.com/kahing/goofys/internal.Buffer.Init.func1(0xc43ec47100, 0xc48c2c0f00)
goroutine 133888 [running]:
github.com/kahing/goofys/internal.(*MBuf).WriteFrom(0xc43ec470c0, 0x7f0c7baab8f8, 0xc42679fce0, 0x7f0c7baab8f8, 0xc42679fce0, 0x1)
/home/khc/Code/go/src/github.com/kahing/goofys/internal/buffer_pool.go:312 +0xff
github.com/kahing/goofys/internal.(*Buffer).readLoop(0xc43ec47100, 0xc48c2c0f00)
/home/khc/Code/go/src/github.com/kahing/goofys/internal/buffer_pool.go:334 +0x99
panic: runtime error: index out of range
/home/khc/Code/go/src/github.com/kahing/goofys/internal/buffer_pool.go:311 +0x35
created by github.com/kahing/goofys/internal.Buffer.Init
/home/khc/Code/go/src/github.com/kahing/goofys/internal/buffer_pool.go:264 +0x1ce
brentp commented 7 years ago

Here is more of the output in case needed:

-----------------------------------------------------
HTTP/1.1 206 Partial Content
Content-Length: 20971520
Accept-Ranges: bytes
Content-Range: bytes 4704811499-4725783018/60866713226
2017/06/19 18:28:58.105527 s3.DEBUG DEBUG: Response s3/GetObject Details:
Date: Mon, 19 Jun 2017 18:28:58 GMT
Etag: "77c26d6315701ab3eae405f71a100d35-7256"
Last-Modified: Tue, 16 May 2017 00:01:35 GMT
Server: AmazonS3
X-Amz-Request-Id: 1231A924894236C4
Content-Type: binary/octet-stream
---[ RESPONSE ]--------------------------------------
2017/06/19 18:28:58.123842 fuse.DEBUG Op 0x00012110 connection.go:479] -> OK ()
2017/06/19 18:28:58.123797 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.126475 fuse.DEBUG Op 0x00012111 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4683943936, 131072 bytes)
2017/06/19 18:28:58.126747 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4683943936 131072]
2017/06/19 18:28:58.136770 fuse.DEBUG Op 0x00012111 connection.go:479] -> OK ()
2017/06/19 18:28:58.136733 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.139504 fuse.DEBUG Op 0x00012112 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4684075008, 131072 bytes)
2017/06/19 18:28:58.139874 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4684075008 131072]
2017/06/19 18:28:58.145410 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.145452 fuse.DEBUG Op 0x00012112 connection.go:479] -> OK ()
2017/06/19 18:28:58.148185 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4684206080 131072]
2017/06/19 18:28:58.147934 fuse.DEBUG Op 0x00012113 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4684206080, 131072 bytes)
2017/06/19 18:28:58.157203 fuse.DEBUG Op 0x00012113 connection.go:479] -> OK ()
2017/06/19 18:28:58.157167 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.159517 fuse.DEBUG Op 0x00012114 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4684337152, 131072 bytes)
2017/06/19 18:28:58.159763 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4684337152 131072]
2017/06/19 18:28:58.165101 fuse.DEBUG Op 0x00012114 connection.go:479] -> OK ()
2017/06/19 18:28:58.165038 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.167465 fuse.DEBUG Op 0x00012115 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4684468224, 131072 bytes)
2017/06/19 18:28:58.167716 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4684468224 131072]
2017/06/19 18:28:58.170768 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.170802 fuse.DEBUG Op 0x00012115 connection.go:479] -> OK ()
2017/06/19 18:28:58.173609 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4684599296 131072]
2017/06/19 18:28:58.173341 fuse.DEBUG Op 0x00012116 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4684599296, 131072 bytes)
2017/06/19 18:28:58.177358 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.177392 fuse.DEBUG Op 0x00012116 connection.go:479] -> OK ()
2017/06/19 18:28:58.180572 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4684730368 131072]
2017/06/19 18:28:58.180223 fuse.DEBUG Op 0x00012117 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4684730368, 131072 bytes)
2017/06/19 18:28:58.181824 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.181939 fuse.DEBUG Op 0x00012117 connection.go:479] -> OK ()
2017/06/19 18:28:58.184749 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4684861440 131072]
2017/06/19 18:28:58.184568 fuse.DEBUG Op 0x00012118 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4684861440, 131072 bytes)
2017/06/19 18:28:58.186821 fuse.DEBUG Op 0x00012118 connection.go:479] -> OK ()
2017/06/19 18:28:58.186785 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.189327 fuse.DEBUG Op 0x00012119 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4684992512, 131072 bytes)
2017/06/19 18:28:58.189499 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4684992512 131072]
2017/06/19 18:28:58.191334 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.191365 fuse.DEBUG Op 0x00012119 connection.go:479] -> OK ()
2017/06/19 18:28:58.194792 fuse.DEBUG Op 0x0001211a connection.go:396] <- ReadFile (inode 78, handle 72, offset 4685123584, 131072 bytes)
2017/06/19 18:28:58.195090 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4685123584 131072]
2017/06/19 18:28:58.197381 fuse.DEBUG Op 0x0001211a connection.go:479] -> OK ()
2017/06/19 18:28:58.197341 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.200847 fuse.DEBUG Op 0x0001211b connection.go:396] <- ReadFile (inode 78, handle 72, offset 4685254656, 131072 bytes)
2017/06/19 18:28:58.201238 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4685254656 131072]
2017/06/19 18:28:58.203476 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.203550 fuse.DEBUG Op 0x0001211b connection.go:479] -> OK ()
2017/06/19 18:28:58.206972 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4685385728 131072]
2017/06/19 18:28:58.206842 fuse.DEBUG Op 0x0001211c connection.go:396] <- ReadFile (inode 78, handle 72, offset 4685385728, 131072 bytes)
2017/06/19 18:28:58.209195 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.209224 fuse.DEBUG Op 0x0001211c connection.go:479] -> OK ()
2017/06/19 18:28:58.211946 fuse.DEBUG Op 0x0001211d connection.go:396] <- ReadFile (inode 78, handle 72, offset 4685516800, 131072 bytes)
2017/06/19 18:28:58.212231 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4685516800 131072]
2017/06/19 18:28:58.215753 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.215793 fuse.DEBUG Op 0x0001211d connection.go:479] -> OK ()
2017/06/19 18:28:58.218301 fuse.DEBUG Op 0x0001211e connection.go:396] <- ReadFile (inode 78, handle 72, offset 4685647872, 131072 bytes)
2017/06/19 18:28:58.218628 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4685647872 131072]
2017/06/19 18:28:58.230153 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.230190 fuse.DEBUG Op 0x0001211e connection.go:479] -> OK ()
2017/06/19 18:28:58.232789 fuse.DEBUG Op 0x0001211f connection.go:396] <- ReadFile (inode 78, handle 72, offset 4685778944, 131072 bytes)
2017/06/19 18:28:58.233159 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4685778944 131072]
2017/06/19 18:28:58.241587 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.241619 fuse.DEBUG Op 0x0001211f connection.go:479] -> OK ()
2017/06/19 18:28:58.243938 fuse.DEBUG Op 0x00012120 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4685910016, 131072 bytes)
2017/06/19 18:28:58.244303 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4685910016 131072]
2017/06/19 18:28:58.251405 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.251441 fuse.DEBUG Op 0x00012120 connection.go:479] -> OK ()
2017/06/19 18:28:58.253939 fuse.DEBUG Op 0x00012121 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4686041088, 131072 bytes)
2017/06/19 18:28:58.254229 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4686041088 131072]
2017/06/19 18:28:58.261588 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.261624 fuse.DEBUG Op 0x00012121 connection.go:479] -> OK ()
2017/06/19 18:28:58.263979 fuse.DEBUG Op 0x00012122 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4686172160, 131072 bytes)
2017/06/19 18:28:58.264297 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4686172160 131072]
2017/06/19 18:28:58.269952 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.269996 fuse.DEBUG Op 0x00012122 connection.go:479] -> OK ()
2017/06/19 18:28:58.272988 fuse.DEBUG Op 0x00012123 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4686303232, 131072 bytes)
2017/06/19 18:28:58.273270 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4686303232 131072]
2017/06/19 18:28:58.282833 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.282866 fuse.DEBUG Op 0x00012123 connection.go:479] -> OK ()
2017/06/19 18:28:58.286151 fuse.DEBUG Op 0x00012124 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4686434304, 131072 bytes)
2017/06/19 18:28:58.286450 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4686434304 131072]
2017/06/19 18:28:58.298800 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.298844 fuse.DEBUG Op 0x00012124 connection.go:479] -> OK ()
2017/06/19 18:28:58.301499 fuse.DEBUG Op 0x00012125 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4686565376, 131072 bytes)
2017/06/19 18:28:58.301776 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4686565376 131072]
2017/06/19 18:28:58.319152 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.319212 fuse.DEBUG Op 0x00012125 connection.go:479] -> OK ()
2017/06/19 18:28:58.322487 fuse.DEBUG Op 0x00012126 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4686696448, 131072 bytes)
2017/06/19 18:28:58.322746 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4686696448 131072]
2017/06/19 18:28:58.342033 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.342130 fuse.DEBUG Op 0x00012126 connection.go:479] -> OK ()
2017/06/19 18:28:58.345860 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4686827520 131072]
2017/06/19 18:28:58.345566 fuse.DEBUG Op 0x00012127 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4686827520, 131072 bytes)
2017/06/19 18:28:58.370146 fuse.DEBUG Op 0x00012127 connection.go:479] -> OK ()
2017/06/19 18:28:58.370051 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.372885 fuse.DEBUG Op 0x00012128 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4686958592, 131072 bytes)
2017/06/19 18:28:58.373097 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4686958592 131072]
2017/06/19 18:28:58.388978 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.389018 fuse.DEBUG Op 0x00012128 connection.go:479] -> OK ()
2017/06/19 18:28:58.391781 fuse.DEBUG Op 0x00012129 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4687089664, 131072 bytes)
2017/06/19 18:28:58.392159 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4687089664 131072]
2017/06/19 18:28:58.409212 fuse.DEBUG Op 0x00012129 connection.go:479] -> OK ()
2017/06/19 18:28:58.409160 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.412265 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4687220736 131072]
2017/06/19 18:28:58.411981 fuse.DEBUG Op 0x0001212a connection.go:396] <- ReadFile (inode 78, handle 72, offset 4687220736, 131072 bytes)
2017/06/19 18:28:58.427891 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.427928 fuse.DEBUG Op 0x0001212a connection.go:479] -> OK ()
2017/06/19 18:28:58.431071 fuse.DEBUG Op 0x0001212b connection.go:396] <- ReadFile (inode 78, handle 72, offset 4687351808, 131072 bytes)
2017/06/19 18:28:58.431426 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4687351808 131072]
2017/06/19 18:28:58.445364 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.445401 fuse.DEBUG Op 0x0001212b connection.go:479] -> OK ()
2017/06/19 18:28:58.447705 fuse.DEBUG Op 0x0001212c connection.go:396] <- ReadFile (inode 78, handle 72, offset 4687482880, 131072 bytes)
2017/06/19 18:28:58.448105 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4687482880 131072]
2017/06/19 18:28:58.453394 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.453431 fuse.DEBUG Op 0x0001212c connection.go:479] -> OK ()
2017/06/19 18:28:58.455983 fuse.DEBUG Op 0x0001212d connection.go:396] <- ReadFile (inode 78, handle 72, offset 4687613952, 131072 bytes)
2017/06/19 18:28:58.456053 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4687613952 131072]
2017/06/19 18:28:58.458393 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.458424 fuse.DEBUG Op 0x0001212d connection.go:479] -> OK ()
2017/06/19 18:28:58.460642 fuse.DEBUG Op 0x0001212e connection.go:396] <- ReadFile (inode 78, handle 72, offset 4687745024, 131072 bytes)
2017/06/19 18:28:58.460774 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4687745024 131072]
2017/06/19 18:28:58.462529 fuse.DEBUG Op 0x0001212e connection.go:479] -> OK ()
2017/06/19 18:28:58.462488 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.464852 fuse.DEBUG Op 0x0001212f connection.go:396] <- ReadFile (inode 78, handle 72, offset 4687876096, 131072 bytes)
2017/06/19 18:28:58.465078 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4687876096 131072]
2017/06/19 18:28:58.468179 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.468212 fuse.DEBUG Op 0x0001212f connection.go:479] -> OK ()
2017/06/19 18:28:58.470161 fuse.DEBUG Op 0x00012130 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4688007168, 131072 bytes)
2017/06/19 18:28:58.470528 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4688007168 131072]
2017/06/19 18:28:58.473562 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.473598 fuse.DEBUG Op 0x00012130 connection.go:479] -> OK ()
2017/06/19 18:28:58.475943 fuse.DEBUG Op 0x00012131 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4688138240, 131072 bytes)
2017/06/19 18:28:58.476188 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4688138240 131072]
2017/06/19 18:28:58.477569 fuse.DEBUG Op 0x00012131 connection.go:479] -> OK ()
2017/06/19 18:28:58.477535 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.479597 fuse.DEBUG Op 0x00012132 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4688269312, 131072 bytes)
2017/06/19 18:28:58.479973 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4688269312 131072]
2017/06/19 18:28:58.481850 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.481962 fuse.DEBUG Op 0x00012132 connection.go:479] -> OK ()
2017/06/19 18:28:58.483910 fuse.DEBUG Op 0x00012133 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4688400384, 131072 bytes)
2017/06/19 18:28:58.484262 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4688400384 131072]
2017/06/19 18:28:58.484958 fuse.DEBUG Op 0x00012133 connection.go:479] -> OK ()
2017/06/19 18:28:58.484927 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.487393 fuse.DEBUG Op 0x00012134 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4688531456, 131072 bytes)
2017/06/19 18:28:58.487758 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4688531456 131072]
2017/06/19 18:28:58.490246 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.490279 fuse.DEBUG Op 0x00012134 connection.go:479] -> OK ()
2017/06/19 18:28:58.492256 fuse.DEBUG Op 0x00012135 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4688662528, 131072 bytes)
2017/06/19 18:28:58.492445 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4688662528 131072]
2017/06/19 18:28:58.494530 fuse.DEBUG Op 0x00012135 connection.go:479] -> OK ()
2017/06/19 18:28:58.494481 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.497906 fuse.DEBUG Op 0x00012136 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4688793600, 131072 bytes)
2017/06/19 18:28:58.498269 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4688793600 131072]
2017/06/19 18:28:58.501187 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.501218 fuse.DEBUG Op 0x00012136 connection.go:479] -> OK ()
2017/06/19 18:28:58.503285 fuse.DEBUG Op 0x00012137 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4688924672, 131072 bytes)
2017/06/19 18:28:58.503546 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4688924672 131072]
2017/06/19 18:28:58.505507 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.505546 fuse.DEBUG Op 0x00012137 connection.go:479] -> OK ()
2017/06/19 18:28:58.508325 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4689055744 131072]
2017/06/19 18:28:58.507986 fuse.DEBUG Op 0x00012138 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4689055744, 131072 bytes)
2017/06/19 18:28:58.554703 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.554762 fuse.DEBUG Op 0x00012138 connection.go:479] -> OK ()
2017/06/19 18:28:58.557593 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.557625 fuse.DEBUG Op 0x00012139 connection.go:479] -> OK ()
2017/06/19 18:28:58.557354 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4689186816 131072]
2017/06/19 18:28:58.556989 fuse.DEBUG Op 0x00012139 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4689186816, 131072 bytes)
2017/06/19 18:28:58.560224 fuse.DEBUG Op 0x0001213a connection.go:396] <- ReadFile (inode 78, handle 72, offset 4689317888, 131072 bytes)
2017/06/19 18:28:58.560462 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4689317888 131072]
2017/06/19 18:28:58.561727 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.561767 fuse.DEBUG Op 0x0001213a connection.go:479] -> OK ()
2017/06/19 18:28:58.563880 fuse.DEBUG Op 0x0001213b connection.go:396] <- ReadFile (inode 78, handle 72, offset 4689448960, 131072 bytes)
2017/06/19 18:28:58.564254 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4689448960 131072]
2017/06/19 18:28:58.572911 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.572964 fuse.DEBUG Op 0x0001213b connection.go:479] -> OK ()
2017/06/19 18:28:58.575313 fuse.DEBUG Op 0x0001213c connection.go:396] <- ReadFile (inode 78, handle 72, offset 4689580032, 131072 bytes)
2017/06/19 18:28:58.575681 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4689580032 131072]
2017/06/19 18:28:58.577314 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.577369 fuse.DEBUG Op 0x0001213c connection.go:479] -> OK ()
2017/06/19 18:28:58.580163 fuse.DEBUG Op 0x0001213d connection.go:396] <- ReadFile (inode 78, handle 72, offset 4689711104, 131072 bytes)
2017/06/19 18:28:58.580496 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4689711104 131072]
2017/06/19 18:28:58.583708 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.583744 fuse.DEBUG Op 0x0001213d connection.go:479] -> OK ()
2017/06/19 18:28:58.586047 fuse.DEBUG Op 0x0001213e connection.go:396] <- ReadFile (inode 78, handle 72, offset 4689842176, 131072 bytes)
2017/06/19 18:28:58.586308 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4689842176 131072]
2017/06/19 18:28:58.589947 fuse.DEBUG Op 0x0001213e connection.go:479] -> OK ()
2017/06/19 18:28:58.589897 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.592988 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4689973248 131072]
2017/06/19 18:28:58.592783 fuse.DEBUG Op 0x0001213f connection.go:396] <- ReadFile (inode 78, handle 72, offset 4689973248, 131072 bytes)
2017/06/19 18:28:58.607396 fuse.DEBUG Op 0x0001213f connection.go:479] -> OK ()
2017/06/19 18:28:58.607347 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.609731 fuse.DEBUG Op 0x00012140 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4690104320, 131072 bytes)
2017/06/19 18:28:58.610040 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4690104320 131072]
2017/06/19 18:28:58.612367 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.612404 fuse.DEBUG Op 0x00012140 connection.go:479] -> OK ()
2017/06/19 18:28:58.615292 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4690235392 131072]
2017/06/19 18:28:58.614919 fuse.DEBUG Op 0x00012141 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4690235392, 131072 bytes)
2017/06/19 18:28:58.618639 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.618716 fuse.DEBUG Op 0x00012141 connection.go:479] -> OK ()
2017/06/19 18:28:58.621223 fuse.DEBUG Op 0x00012142 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4690366464, 131072 bytes)
2017/06/19 18:28:58.621456 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4690366464 131072]
2017/06/19 18:28:58.623764 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.623800 fuse.DEBUG Op 0x00012142 connection.go:479] -> OK ()
2017/06/19 18:28:58.626607 fuse.DEBUG Op 0x00012143 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4690497536, 131072 bytes)
2017/06/19 18:28:58.626949 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4690497536 131072]
2017/06/19 18:28:58.630354 fuse.DEBUG Op 0x00012143 connection.go:479] -> OK ()
2017/06/19 18:28:58.630316 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.632561 fuse.DEBUG Op 0x00012144 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4690628608, 131072 bytes)
2017/06/19 18:28:58.632927 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4690628608 131072]
2017/06/19 18:28:58.639687 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.639718 fuse.DEBUG Op 0x00012144 connection.go:479] -> OK ()
2017/06/19 18:28:58.642031 fuse.DEBUG Op 0x00012145 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4690759680, 131072 bytes)
2017/06/19 18:28:58.642392 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4690759680 131072]
2017/06/19 18:28:58.654458 fuse.DEBUG Op 0x00012146 connection.go:396] <- ReadFile (inode 78, handle 72, offset 4690632704, 65536 bytes)
2017/06/19 18:28:58.654265 fuse.DEBUG Op 0x00012145 connection.go:479] -> OK ()
2017/06/19 18:28:58.654184 fuse.DEBUG < ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [0 <nil>]
2017/06/19 18:28:58.654830 fuse.DEBUG ReadFile 78 sarcoma/764-SS-767/764-SS-767.bam [4690632704 65536]
2017/06/19 18:28:58.654848 fuse.DEBUG out of order read 78 sarcoma/764-SS-767/764-SS-767.bam [4690632704 4690890752]
panic: runtime error: index out of range
goroutine 133887 [running]:
github.com/kahing/goofys/internal.(*MBuf).WriteFrom(0xc43ec47000, 0x7f0c7baab8f8, 0xc43c2ca980, 0x7f0c7baab8f8, 0xc43c2ca980, 0x1)
created by github.com/kahing/goofys/internal.Buffer.Init
/home/khc/Code/go/src/github.com/kahing/goofys/internal/buffer_pool.go:312 +0xff
/home/khc/Code/go/src/github.com/kahing/goofys/internal/buffer_pool.go:264 +0x1ce
github.com/kahing/goofys/internal.Buffer.Init.func1(0xc43ec47040, 0xc48c2c0e40)
/home/khc/Code/go/src/github.com/kahing/goofys/internal/buffer_pool.go:311 +0x35
/home/khc/Code/go/src/github.com/kahing/goofys/internal/buffer_pool.go:334 +0x99
github.com/kahing/goofys/internal.(*Buffer).readLoop(0xc43ec47040, 0xc48c2c0e40)
github.com/kahing/goofys/internal.Buffer.Init.func1(0xc43ec47100, 0xc48c2c0f00)
goroutine 133888 [running]:
github.com/kahing/goofys/internal.(*MBuf).WriteFrom(0xc43ec470c0, 0x7f0c7baab8f8, 0xc42679fce0, 0x7f0c7baab8f8, 0xc42679fce0, 0x1)
/home/khc/Code/go/src/github.com/kahing/goofys/internal/buffer_pool.go:312 +0xff
github.com/kahing/goofys/internal.(*Buffer).readLoop(0xc43ec47100, 0xc48c2c0f00)
/home/khc/Code/go/src/github.com/kahing/goofys/internal/buffer_pool.go:334 +0x99
panic: runtime error: index out of range
/home/khc/Code/go/src/github.com/kahing/goofys/internal/buffer_pool.go:311 +0x35
created by github.com/kahing/goofys/internal.Buffer.Init
/home/khc/Code/go/src/github.com/kahing/goofys/internal/buffer_pool.go:264 +0x1ce
brentp commented 7 years ago

here's one with GOMAXPROCS=1 that makes the problem more clear (note the [0 <nil>]). I haven't looked too much at the code, but I'll try to submit a PR to fix this.

2017/06/19 21:25:33.469493 fuse.DEBUG out of order read 261 sarcoma/631-SS-634/631-SS-634.bam [24987619328 24987877376]
2017/06/19 21:25:33.468961 fuse.DEBUG Op 0x00014357 connection.go:479] -> OK ()
2017/06/19 21:25:33.469098 fuse.DEBUG Op 0x00014358 connection.go:396] <- ReadFile (inode 261, handle 255, offset 24987619328, 4096 bytes)
2017/06/19 21:25:33.469474 fuse.DEBUG ReadFile 261 sarcoma/631-SS-634/631-SS-634.bam [24987619328 4096]
2017/06/19 21:25:33.468908 fuse.DEBUG < ReadFile 261 sarcoma/631-SS-634/631-SS-634.bam [0 <nil>]
panic: runtime error: index out of range
goroutine 110128 [running]:
github.com/kahing/goofys/internal.(*MBuf).WriteFrom(0xc61171a9c0, 0x7f7df7336dc8, 0xc42240c2e0, 0x7f7df7336dc8, 0xc42240c2e0, 0x1)
/home/khc/Code/go/src/github.com/kahing/goofys/internal/buffer_pool.go:312 +0xff
github.com/kahing/goofys/internal.(*Buffer).readLoop(0xc61171aa00, 0xc718d060c0)
/home/khc/Code/go/src/github.com/kahing/goofys/internal/buffer_pool.go:334 +0x99
github.com/kahing/goofys/internal.Buffer.Init.func1(0xc61171aa00, 0xc718d060c0)
/home/khc/Code/go/src/github.com/kahing/goofys/internal/buffer_pool.go:311 +0x35
created by github.com/kahing/goofys/internal.Buffer.Init
/home/khc/Code/go/src/github.com/kahing/goofys/internal/buffer_pool.go:264 +0x1ce
brentp commented 7 years ago

I made the change posted below to fix all cases where I saw this error. I assume it is when 0-length reads are requested but I didn't know how to write a test for this case.

diff --git a/internal/buffer_pool.go b/internal/buffer_pool.go
index 9fc570e..e98646b 100644
--- a/internal/buffer_pool.go
+++ b/internal/buffer_pool.go
@@ -261,6 +261,9 @@ func (mb *MBuf) Write(p []byte) (n int, err error) {
 }

 func (mb *MBuf) WriteFrom(r io.Reader) (n int, err error) {
+       if mb.wbuf >= len(mb.buffers) {
+               return
+       }
        b := mb.buffers[mb.wbuf]

        if mb.wp == cap(b) {
kahing commented 7 years ago

Sorry for the delay, just came back from vacation.

2017/06/19 21:25:33.469474 fuse.DEBUG ReadFile 261 sarcoma/631-SS-634/631-SS-634.bam [24987619328 4096]
2017/06/19 21:25:33.468908 fuse.DEBUG < ReadFile 261 sarcoma/631-SS-634/631-SS-634.bam [0 <nil>]

means you are reading 4K at 24987619328 but got 0 bytes and no error, how large is the file?

brentp commented 7 years ago

That file is 61317031394 bytes.

kahing commented 7 years ago

your fix suggests that there are more bytes available in the http stream than there is space allocated in the buffer. and indeed this test reproduces the same backtrace:

func (s *BufferTest) TestIssue193(t *C) {
    h := NewBufferPool(1000 * 1024 * 1024)

    n := uint64(2 * BUF_SIZE)
    mb := MBuf{}.Init(h, 0, false)

    r := func() (io.ReadCloser, error) {
        return &SlowReader{io.LimitReader(&SeqReader{}, int64(n)), 1 * time.Millisecond}, nil
    }

    b := Buffer{}.Init(mb, r)

    // let the readloop read
    time.Sleep(1000 * time.Millisecond)
    b.Close()
}

However, I don't quite see how that can happen. The relevant code is in handles.go:570 in

func (b S3ReadBuffer) Init(fs *Goofys, fh *FileHandle, offset uint64, size uint32) *S3ReadBuffer {

There we allocate the buffer with size and request offset to offset + size - 1, and the latter should never return more bytes than size.

The other possibility is if Buffer.buf has been freed, and that can only happen if Buffer.Close() is called in between readLoop. Checking in a fix for that.

kahing commented 7 years ago

thanks for the report and debugging @brentp!

brentp commented 7 years ago

thank you!

brentp commented 7 years ago

actually, with your change, I now get:

panic: not the right buffer, expecting 5408976896 got 5409069082, 5790351 left
goroutine 67740 [running]:
github.com/kahing/goofys/internal.(*S3ReadBuffer).Read(0xc429960fe0, 0x14267d81a, 0xc427454832, 0x97e6, 0x97e6, 0xc42028aad0, 0xc420053df0, 0x18)
/home/brentp/go/src/github.com/kahing/goofys/internal/handles.go:620 +0x3d0
github.com/kahing/goofys/internal.(*FileHandle).readFromReadAhead(0xc42016e820, 0xc4200c72c0, 0x14267d81a, 0xc427454832, 0x97e6, 0x97e6, 0x1681a, 0xc43720, 0xc428dbe000)
/home/brentp/go/src/github.com/kahing/goofys/internal/handles.go:629 +0xa5
github.com/kahing/goofys/internal.(*FileHandle).readFile(0xc42016e820, 0xc4200c72c0, 0x14267d81a, 0xc427454832, 0x97e6, 0x97e6, 0x0, 0x0, 0x0)
/home/brentp/go/src/github.com/kahing/goofys/internal/handles.go:775 +0x3b0
github.com/kahing/goofys/internal.(*FileHandle).ReadFile(0xc42016e820, 0xc4200c72c0, 0x142667000, 0xc42743e018, 0x20000, 0x20000, 0x1681a, 0x0, 0x0)
/home/brentp/go/src/github.com/kahing/goofys/internal/handles.go:705 +0x304
github.com/kahing/goofys/internal.(*Goofys).ReadFile(0xc4200c72c0, 0x7fa477509c48, 0xc428918150, 0xc42a5b6800, 0x0, 0x0)
/home/brentp/go/src/github.com/kahing/goofys/internal/goofys.go:985 +0xd5
github.com/jacobsa/fuse/fuseutil.(*fileSystemServer).handleOp(0xc4202282a0, 0xc420154180, 0x7fa477509c48, 0xc428918150, 0x8b97a0, 0xc42a5b6800)
/home/brentp/go/src/github.com/jacobsa/fuse/fuseutil/file_system.go:177 +0xadc
created by github.com/jacobsa/fuse/fuseutil.(*fileSystemServer).ServeOps
brentp commented 7 years ago

here's another traceback:


2017/06/21 19:43:17.926013 fuse.DEBUG < readFromStream 243 sarcoma/1073-SS-1077/1073-SS-1077.bam [16360]
2017/06/21 19:43:17.926057 fuse.DEBUG < readFromStream 243 sarcoma/1073-SS-1077/1073-SS-1077.bam [24]
2017/06/21 19:43:17.926068 fuse.DEBUG < ReadFile 243 sarcoma/1073-SS-1077/1073-SS-1077.bam [0 <nil>]
2017/06/21 19:43:17.929864 fuse.DEBUG Op 0x00012fca connection.go:479] -> OK ()
2017/06/21 19:43:20.192235 fuse.DEBUG Op 0x00012fcb connection.go:396] <- ReadFile (inode 243, handle 237, offset 4835459072, 65536 bytes)
2017/06/21 19:43:20.771566 fuse.DEBUG ReadFile 243 sarcoma/1073-SS-1077/1073-SS-1077.bam [4835459072 65536]
2017/06/21 19:43:21.318588 fuse.DEBUG out of order read 243 sarcoma/1073-SS-1077/1073-SS-1077.bam [4835459072 4835471360]
kahing commented 7 years ago

is there supposed to be more output from the last paste?

brentp commented 7 years ago

after that it just shows the process was killed with a message like:

/mnt/local/tmp.t1ChHORzwt: line 48: 157 Killed ./goofys --debug_fuse --debug_s3 -f ${s3base} /mnt/${s3base}

(That tmp fie line 48 is the name of the script that is running) Here is another different one:

Last-Modified: Tue, 16 May 2017 11:21:05 GMT
Server: AmazonS3
X-Amz-Id-2: 58XPDGa5EfVJkrgcK/cl4ykOLG4krESZEVwkjfgdazMMYWSPm/xWhCO+VuP+cxLQFXm2PsLtDlM=
X-Amz-Request-Id: E225E6226C01A5E6
Content-Type: binary/octet-stream
Content-Length: 20971520
2017/06/21 19:37:16.666226 s3.DEBUG DEBUG: Response s3/GetObject Details:
---[ RESPONSE ]--------------------------------------
HTTP/1.1 206 Partial Content
Content-Length: 20971520
Accept-Ranges: bytes
Content-Range: bytes 36813982134-36834953653/67474772069
Content-Type: binary/octet-stream
Date: Wed, 21 Jun 2017 19:37:17 GMT
Etag: "cb7ea3cb6f3822e31f6b3840267160eb-8044"
Last-Modified: Tue, 16 May 2017 11:21:05 GMT
Server: AmazonS3
X-Amz-Id-2: Q+y3C3n7oElnxgowJqgCwpo0Nsj+U0sgIhmTmVBDV4gBYKs/rqkRCWYuJoOPRnOdAt416m1LU8U=
X-Amz-Request-Id: 510E24A1C32A66DD

-----------------------------------------------------
2017/06/21 19:37:16.675926 fuse.DEBUG < ReadFile 117 sarcoma/218-SS-218/218-SS-218.bam [0 <nil>]
2017/06/21 19:37:16.675969 fuse.DEBUG Op 0x00010e3a connection.go:479] -> OK ()
2017/06/21 19:37:16.683990 fuse.DEBUG ReadFile 135 sarcoma/184-SS-184/184-SS-184.bam [31650578432 131072]
2017/06/21 19:37:16.683723 fuse.DEBUG Op 0x00010e3b connection.go:396] <- ReadFile (inode 135, handle 129, offset 31650578432, 131072 bytes)
2017/06/21 19:37:16.684030 fuse.DEBUG < readFromStream 135 sarcoma/184-SS-184/184-SS-184.bam [4646]
2017/06/21 19:37:16.684087 fuse.DEBUG < readFromStream 135 sarcoma/184-SS-184/184-SS-184.bam [1048]
2017/06/21 19:37:16.684139 fuse.DEBUG < readFromStream 135 sarcoma/184-SS-184/184-SS-184.bam [16360]
2017/06/21 19:37:16.684162 fuse.DEBUG < readFromStream 135 sarcoma/184-SS-184/184-SS-184.bam [1048]
2017/06/21 19:37:16.684205 fuse.DEBUG < readFromStream 135 sarcoma/184-SS-184/184-SS-184.bam [16360]
2017/06/21 19:37:16.684580 fuse.DEBUG Op 0x00010e3b connection.go:479] -> OK ()
2017/06/21 19:37:16.684265 fuse.DEBUG < readFromStream 135 sarcoma/184-SS-184/184-SS-184.bam [16360]
2017/06/21 19:37:16.684280 fuse.DEBUG < readFromStream 135 sarcoma/184-SS-184/184-SS-184.bam [1048]
2017/06/21 19:37:16.684324 fuse.DEBUG < readFromStream 135 sarcoma/184-SS-184/184-SS-184.bam [16360]
2017/06/21 19:37:16.684342 fuse.DEBUG < readFromStream 135 sarcoma/184-SS-184/184-SS-184.bam [1048]
2017/06/21 19:37:16.684385 fuse.DEBUG < readFromStream 135 sarcoma/184-SS-184/184-SS-184.bam [16360]
2017/06/21 19:37:16.684541 fuse.DEBUG < ReadFile 135 sarcoma/184-SS-184/184-SS-184.bam [0 <nil>]
2017/06/21 19:37:16.684444 fuse.DEBUG < readFromStream 135 sarcoma/184-SS-184/184-SS-184.bam [16360]
2017/06/21 19:37:16.684459 fuse.DEBUG < readFromStream 135 sarcoma/184-SS-184/184-SS-184.bam [1048]
2017/06/21 19:37:16.684489 fuse.DEBUG < readFromStream 135 sarcoma/184-SS-184/184-SS-184.bam [16360]
2017/06/21 19:37:16.684503 fuse.DEBUG < readFromStream 135 sarcoma/184-SS-184/184-SS-184.bam [1048]
2017/06/21 19:37:16.684527 fuse.DEBUG < readFromStream 135 sarcoma/184-SS-184/184-SS-184.bam [3522]
2017/06/21 19:37:16.684227 fuse.DEBUG < readFromStream 135 sarcoma/184-SS-184/184-SS-184.bam [1048]
2017/06/21 19:37:16.684402 fuse.DEBUG < readFromStream 135 sarcoma/184-SS-184/184-SS-184.bam [1048]
2017/06/21 19:37:16.691377 fuse.DEBUG Op 0x00010e3c connection.go:396] <- ReadFile (inode 153, handle 147, offset 34323304448, 131072 bytes)
2017/06/21 19:37:16.691786 fuse.DEBUG < readFromStream 153 sarcoma/20-SS-20/20-SS-20.bam [0]
2017/06/21 19:37:16.691694 fuse.DEBUG ReadFile 153 sarcoma/20-SS-20/20-SS-20.bam [34323304448 131072]
2017/06/21 19:37:16.691719 fuse.DEBUG < readFromStream 153 sarcoma/20-SS-20/20-SS-20.bam [3814]
2017/06/21 19:37:16.691739 fuse.DEBUG < readFromStream 153 sarcoma/20-SS-20/20-SS-20.bam [12264]
2017/06/21 19:37:16.691761 fuse.DEBUG < readFromStream 153 sarcoma/20-SS-20/20-SS-20.bam [1048]
2017/06/21 19:37:16.691801 fuse.DEBUG < ReadFile 153 sarcoma/20-SS-20/20-SS-20.bam [0 <nil>]
2017/06/21 19:37:16.691837 fuse.DEBUG Op 0x00010e3c connection.go:481] -> Error: "read tcp 172.31.1.110:44448->54.231.72.90:443: read: connection reset by peer"
2017/06/21 19:37:16.699426 fuse.DEBUG ReadFile 171 sarcoma/557-SS-560/557-SS-560.bam [36872896512 131072]
2017/06/21 19:37:16.699079 fuse.DEBUG Op 0x00010e3d connection.go:396] <- ReadFile (inode 171, handle 165, offset 36872896512, 131072 bytes)
2017/06/21 19:37:16.699456 fuse.DEBUG < readFromStream 171 sarcoma/557-SS-560/557-SS-560.bam [574]
2017/06/21 19:37:16.699507 fuse.DEBUG < readFromStream 171 sarcoma/557-SS-560/557-SS-560.bam [16360]
2017/06/21 19:37:16.699555 fuse.DEBUG < readFromStream 171 sarcoma/557-SS-560/557-SS-560.bam [1048]
2017/06/21 19:37:16.699607 fuse.DEBUG < readFromStream 171 sarcoma/557-SS-560/557-SS-560.bam [16360]
2017/06/21 19:37:16.699622 fuse.DEBUG < readFromStream 171 sarcoma/557-SS-560/557-SS-560.bam [1048]
2017/06/21 19:37:16.699683 fuse.DEBUG < readFromStream 171 sarcoma/557-SS-560/557-SS-560.bam [16360]
2017/06/21 19:37:16.699702 fuse.DEBUG < readFromStream 171 sarcoma/557-SS-560/557-SS-560.bam [1048]
2017/06/21 19:37:16.699726 fuse.DEBUG < readFromStream 171 sarcoma/557-SS-560/557-SS-560.bam [16360]
2017/06/21 19:37:16.699739 fuse.DEBUG < readFromStream 171 sarcoma/557-SS-560/557-SS-560.bam [1048]
2017/06/21 19:37:16.700097 fuse.DEBUG Op 0x00010e3d connection.go:479] -> OK ()
2017/06/21 19:37:16.699822 fuse.DEBUG < readFromStream 171 sarcoma/557-SS-560/557-SS-560.bam [1048]
2017/06/21 19:37:16.699865 fuse.DEBUG < readFromStream 171 sarcoma/557-SS-560/557-SS-560.bam [16360]
2017/06/21 19:37:16.699926 fuse.DEBUG < readFromStream 171 sarcoma/557-SS-560/557-SS-560.bam [1048]
2017/06/21 19:37:16.699800 fuse.DEBUG < readFromStream 171 sarcoma/557-SS-560/557-SS-560.bam [16360]
2017/06/21 19:37:16.699988 fuse.DEBUG < readFromStream 171 sarcoma/557-SS-560/557-SS-560.bam [1048]
2017/06/21 19:37:16.700017 fuse.DEBUG < readFromStream 171 sarcoma/557-SS-560/557-SS-560.bam [8642]
2017/06/21 19:37:16.700054 fuse.DEBUG < ReadFile 171 sarcoma/557-SS-560/557-SS-560.bam [0 <nil>]
2017/06/21 19:37:16.699960 fuse.DEBUG < readFromStream 171 sarcoma/557-SS-560/557-SS-560.bam [16360]
2017/06/21 19:37:16.703474 fuse.DEBUG Op 0x00010e3e connection.go:396] <- ReadFile (inode 180, handle 174, offset 27422400512, 131072 bytes)
2017/06/21 19:37:16.703764 fuse.DEBUG ReadFile 180 sarcoma/288-SS-288/288-SS-288.bam [27422400512 131072]
2017/06/21 19:37:16.703979 fuse.DEBUG < ReadFile 180 sarcoma/288-SS-288/288-SS-288.bam [0 <nil>]
/home/brentp/go/src/github.com/jacobsa/fuse/fuseutil/file_system.go:112 +0x12a
goroutine 93004 [running]:
github.com/kahing/goofys/internal.(*S3ReadBuffer).Read(0xc4384f1d20, 0x662823937, 0xc42055194f, 0x66c9, 0x66c9, 0xc4203dcd50, 0xc575c67df0, 0x18)
/home/brentp/go/src/github.com/kahing/goofys/internal/handles.go:620 +0x3d0
github.com/kahing/goofys/internal.(*FileHandle).readFromReadAhead(0xc4201aa4e0, 0xc4200d72c0, 0x662823937, 0xc42055194f, 0x66c9, 0x66c9, 0x19937, 0xc43720, 0xc43bc22a00)
/home/brentp/go/src/github.com/kahing/goofys/internal/handles.go:629 +0xa5
github.com/kahing/goofys/internal.(*FileHandle).readFile(0xc4201aa4e0, 0xc4200d72c0, 0x662823937, 0xc42055194f, 0x66c9, 0x66c9, 0x0, 0x0, 0x0)
/home/brentp/go/src/github.com/kahing/goofys/internal/handles.go:775 +0x3b0
github.com/kahing/goofys/internal.(*FileHandle).ReadFile(0xc4201aa4e0, 0xc4200d72c0, 0x66280a000, 0xc420538018, 0x20000, 0x20000, 0x19937, 0x0, 0x0)
/home/brentp/go/src/github.com/kahing/goofys/internal/handles.go:705 +0x304
panic: not the right buffer, expecting 27422400512 got 27422505271, 19307742 left
/home/brentp/go/src/github.com/kahing/goofys/internal/goofys.go:985 +0xd5
github.com/jacobsa/fuse/fuseutil.(*fileSystemServer).handleOp(0xc420191720, 0xc42017a600, 0x7fbd748abcc0, 0xc42bd1a030, 0x8b97a0, 0xc425fd5f80)
/home/brentp/go/src/github.com/jacobsa/fuse/fuseutil/file_system.go:177 +0xadc
created by github.com/jacobsa/fuse/fuseutil.(*fileSystemServer).ServeOps
github.com/kahing/goofys/internal.(*Goofys).ReadFile(0xc4200d72c0, 0x7fbd748abcc0, 0xc42bd1a030, 0xc425fd5f80, 0x0, 0x0)
kahing commented 7 years ago

I am a bit busy the next couple days but will try to look at this over the weekend. Is there a way for me to reproduce this? Feel free to email me the details if it's private.

brentp commented 7 years ago

sorry for the delay. was trying to come up with a small reproducer, but no luck. This happens from a program that's accessing ~100 files each of size ~50GB. It has a lot of seeks where it will seek to a new region in each of the 100 files several thousand times.

kahing commented 7 years ago

How much does it usually read in each region?

brentp commented 7 years ago

probably 16KB-128KB per region (per file)

kahing commented 7 years ago

As a workaround, could you try --cheap?

kahing commented 7 years ago

I think the last commit fixed the case without --cheap, could you try and report back?

brentp commented 7 years ago

thanks for the fix. I doesn't seem to panic. With debug on, I do see "error" messages like below. Not sure if these are ok to ignore.

2017/06/28 15:19:17.838389 s3.DEBUG DEBUG: Validate Response s3/HeadObject failed, not retrying, error NotFound: Not Found
2017/06/28 15:19:17.858056 s3.DEBUG DEBUG: Validate Response s3/HeadObject failed, not retrying, error NotFound: Not Found
2017/06/28 15:19:17.881931 s3.DEBUG DEBUG: Validate Response s3/HeadObject failed, not retrying, error NotFound: Not Found
2017/06/28 15:19:17.894213 s3.DEBUG DEBUG: Validate Response s3/HeadObject failed, not retrying, error NotFound: Not Found
2017/06/28 15:19:17.904209 s3.DEBUG DEBUG: Validate Response s3/HeadObject failed, not retrying, error NotFound: Not Found
2017/06/28 15:19:17.986255 s3.DEBUG DEBUG: Validate Response s3/HeadObject failed, not retrying, error NotFound: Not Found
2017/06/28 15:19:53.272090 fuse.DEBUG < readFromStream error 7 assets/GRCh37/GRCh37.fa.fai [2746 EOF]
2017/06/28 15:19:53.292402 s3.DEBUG DEBUG: Validate Response s3/HeadObject failed, not retrying, error NotFound: Not Found
2017/06/28 15:19:53.295666 s3.DEBUG DEBUG: Validate Response s3/HeadObject failed, not retrying, error NotFound: Not Found
2017/06/28 15:19:53.297408 s3.DEBUG DEBUG: Validate Response s3/HeadObject failed, not retrying, error NotFound: Not Found
2017/06/28 15:19:53.351112 s3.DEBUG DEBUG: Validate Response s3/HeadObject failed, not retrying, error NotFound: Not Found
2017/06/28 15:19:54.769305 fuse.DEBUG < readFromStream error 9 sarcoma/856-SS-859/856-SS-859.bam [375 EOF]
kahing commented 7 years ago

Yes they are fine

brentp commented 7 years ago

this seems to have resolved those issues. thanks very much.