'ipfs add' stack trace while daemon is running

[louisbourque]

Version/Platform/Processor information:

$ ipfs version --all
go-ipfs version: 0.4.3-rc2-
Repo version: 4
System version: arm/linux
Golang version: go1.6.2

$ uname -a
Linux ipfs 4.4.11-v7+ #888 SMP Mon May 23 20:10:33 BST 2016 armv7l GNU/Linux

Type: bug
Area: commands
Priority: P1

Description:

If I try to run ipfs add file while ipfs daemon is running, I get a stack trace. If I stop the daemon, and try again it works fine. 'file' is just a text file in the current directory.

While ipfs daemon is running:

$ ipfs add file
goroutine 1 [running]:
runtime/debug.Stack(0x0, 0x0, 0x0)
    /home/whyrusleeping/go/src/runtime/debug/stack.go:24 +0x84
runtime/debug.PrintStack()
    /home/whyrusleeping/go/src/runtime/debug/stack.go:16 +0x14
gx/ipfs/QmZNVWh8LLjAavuQ2JXuFmuYH3C11xo988vSgp7UQrTRj1/go-ipfs-util.ErrCast(0x0, 0x0)
    /builds/distributions/dists/go-ipfs/gopath/src/gx/ipfs/QmZNVWh8LLjAavuQ2JXuFmuYH3C11xo988vSgp7UQrTRj1/go-ipfs-util/util.go:34 +0x20
github.com/ipfs/go-ipfs/core/commands.glob.func7(0x76eb4130, 0x112a00c0, 0x76ef9550, 0x11062480)
    /builds/distributions/dists/go-ipfs/gopath/src/github.com/ipfs/go-ipfs/core/commands/add.go:223 +0x9c
main.callCommand(0x76eb4230, 0x110f6e40, 0x76eb4130, 0x112a00c0, 0xe9f888, 0xe85830, 0x0, 0x0, 0x0, 0x0)
    /builds/distributions/dists/go-ipfs/gopath/src/github.com/ipfs/go-ipfs/cmd/ipfs/main.go:351 +0x6e0
main.(*cmdInvocation).Run(0x110f6b80, 0x76eb4230, 0x110f6e40, 0x0, 0x0, 0x0, 0x0)
    /builds/distributions/dists/go-ipfs/gopath/src/github.com/ipfs/go-ipfs/cmd/ipfs/main.go:189 +0x1a0
main.main()
    /builds/distributions/dists/go-ipfs/gopath/src/github.com/ipfs/go-ipfs/cmd/ipfs/main.go:154 +0x65c
Error: cast error

While ipfs daemon is stopped:

$ sudo killall ipfs
$ ipfs add file
added QmeomffUNfmQy76CQGy9NdmqEnnHU9soCexBnGU3ezPHVH file

[whyrusleeping]

@louisbourque are you sure that binary youre using for ipfs daemon and the binary youre using for ipfs add are the same? I'm able to reproduce the above issue by running ipfs daemon with code from 0.4.2, and the ipfs add with 0.4.3-rc

I havent tried on a raspberry pi yet because i don't have one handy at the moment, but i'm fairly certain that won't be an issue

[Kubuxu]

@whyrusleeping we have checks for that, cli won't execute commands at the daemon even if it is 0.4.3-rc1 vs 0.4.3-rc2.

[whyrusleeping]

@Kubuxu yes, it will. try it.

[louisbourque]

@whyrusleeping The binaries should be the same one. I never had 0.4.2 installed on this Raspberry Pi. The first one I got was go-ipfs_v0.4.3-rc1_linux-arm.tar.gz. I got this error with that version too, so I checked for an upgrade and found go-ipfs_v0.4.3-rc2_linux-arm.tar.gz.

Just to make sure, here is the flow I can use to reproduce the error, all in the same shell session, so it should always be the same ipfs binary.

(added ****** to highlight the commands I typed in)

louis@ipfs:~$ which ipfs******
/usr/local/bin/ipfs
louis@ipfs:~$ ipfs add file******
added QmeomffUNfmQy76CQGy9NdmqEnnHU9soCexBnGU3ezPHVH file
louis@ipfs:~$ ipfs daemon &******
[1] 817
louis@ipfs:~$ Initializing daemon...
Swarm listening on /ip4/127.0.0.1/tcp/4001
Swarm listening on /ip4/192.168.2.5/tcp/4001
Swarm listening on /ip4/198.48.152.58/tcp/4001
Swarm listening on /ip6/::1/tcp/4001
API server listening on /ip4/192.168.2.5/tcp/5001
Gateway (readonly) server listening on /ip4/192.168.2.5/tcp/8080
Daemon is ready
ipfs add file******
goroutine 1 [running]:
runtime/debug.Stack(0x0, 0x0, 0x0)
    /home/whyrusleeping/go/src/runtime/debug/stack.go:24 +0x84
runtime/debug.PrintStack()
    /home/whyrusleeping/go/src/runtime/debug/stack.go:16 +0x14
gx/ipfs/QmZNVWh8LLjAavuQ2JXuFmuYH3C11xo988vSgp7UQrTRj1/go-ipfs-util.ErrCast(0x0, 0x0)
    /builds/distributions/dists/go-ipfs/gopath/src/gx/ipfs/QmZNVWh8LLjAavuQ2JXuFmuYH3C11xo988vSgp7UQrTRj1/go-ipfs-util/util.go:34 +0x20
github.com/ipfs/go-ipfs/core/commands.glob.func7(0x76f0cb58, 0x111dd800, 0x76ed0758, 0x11062800)
    /builds/distributions/dists/go-ipfs/gopath/src/github.com/ipfs/go-ipfs/core/commands/add.go:223 +0x9c
main.callCommand(0x76f0cc58, 0x111f7c40, 0x76f0cb58, 0x111dd800, 0xe9f888, 0xe85830, 0x0, 0x0, 0x0, 0x0)
    /builds/distributions/dists/go-ipfs/gopath/src/github.com/ipfs/go-ipfs/cmd/ipfs/main.go:351 +0x6e0
main.(*cmdInvocation).Run(0x111f7980, 0x76f0cc58, 0x111f7c40, 0x0, 0x0, 0x0, 0x0)
    /builds/distributions/dists/go-ipfs/gopath/src/github.com/ipfs/go-ipfs/cmd/ipfs/main.go:189 +0x1a0
main.main()
    /builds/distributions/dists/go-ipfs/gopath/src/github.com/ipfs/go-ipfs/cmd/ipfs/main.go:154 +0x65c
Error: cast error

[louisbourque]

After some debugging, it seems this issue is caused by a combination of my use of a proxy server and the Go HTTP request setting a content length of 0.

When the daemon is running, the command is executed via the API instead of locally. The HTTP request is made with a Content-Length of 0, which Squid proxy sees as invalid:

&{%!s(*http.Response=&{411 Length Required 411 HTTP/1.0 1 0 map[Content-Length:[2105] Connection:[close] Server:[squid/2.7.STABLE9] Content-Type:[text/html] X-Squid-Error:[ERR_INVALID_REQ 0]...

If I manually set the content length (httpReq.ContentLength = 224) the request works. I tried setting the content length based on actual data:

b, err := ioutil.ReadAll(reader)
if err != nil {
    log.Fatal(err)
}
httpReq.ContentLength = int64(len(b))

but this consumes the contents of reader. I'm not familiar with Go, but it seems the only way is to read the contents into memory twice (once for the length, and again for the actual http request.) I'm not sure it's worth it for such a rare case. It seems this is a bug in the implementation of Go, as ContentLength should be set by http.NewRequest("POST", url, reader), but it is not.

[whyrusleeping]

Are we explicitly setting a length of zero? Afaik we use chunked encoding
and don't touch content length.

On Mon, Aug 15, 2016, 13:06 Louis Bourque notifications@github.com wrote:

After some debugging, it seems this issue is caused by a combination of my
use of a proxy server and the Go HTTP request setting a content length of 0.

When the daemon is running, the command is executed via the API instead of
locally. The HTTP request is made with a Content-Length of 0, which Squid
proxy sees as invalid:

&{%!s(*http.Response=&{411 Length Required 411 HTTP/1.0 1 0 map[Content-Length:[2105] Connection:[close] Server:[squid/2.7.STABLE9] Content-Type:[text/html] X-Squid-Error:[ERR_INVALID_REQ 0]...

If I manually set the content length (httpReq.ContentLength = 224) the
request works. I tried setting the content length based on actual data:

b, err := ioutil.ReadAll(reader)
if err != nil {
log.Fatal(err)
}
httpReq.ContentLength = int64(len(b))

but this consumes the contents of reader. I'm not familiar with Go, but it
seems the only way is to read the contents into memory twice (once for the
length, and again for the actual http request.) I'm not sure it's worth it
for such a rare case. It seems this is a bug in the implementation of Go,
as ContentLength should be set by http.NewRequest("POST", url, reader),
but it is not.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#3075 (comment), or mute
the thread
https://github.com/notifications/unsubscribe-auth/ABL4HBmM121my22ZfZe73R01O1S1htZNks5qgMasgaJpZM4Jik2v
.

[louisbourque]

As far as I can see, IPFS isn't setting the content length at all. Looking at the documentation for net/http, I would say the length should be determined by http.NewRequest. This test(around line 400) even checks to make sure that it did.
The difference may be that they use String reader, and we're using File reader. Maybe the length can't be determined ahead of time for a file.

[whyrusleeping]

That sounds correct. The http spec allows you to either set content length, or use chunked encoding. I'm assuming that your proxy doesnt understand chunked-encoding and is failing to pass that header down to the daemon.