PayloadReader doesn't work all the time

[Saxon Milton]

When pushing video over http to netreceiver/vidgrind running on dev appserver, a bug is exposed; caused by the PayloadReader in netsender.go that we pass to http.Post() - not sure why it doesn't break things when pushing to the cloud though. If bytes.NewReader(Pins[0].Data) is used instead to give http.Post() a reader, it works fine.

[kortschak]

Can you post a reproducer/more detail?

[kortschak]

The code in PayloadReader.Read is doing what it says it will. Are you giving it the wrong pins?

If you replace the call to NewPayloadReader with a call to the following func, what happens?

func joinedReader(pins []netsender.Pin) *bytes.Reader {
    var r []io.Reader
    for _, p := range pins {
        r = append(r, bytes.NewReader(p.Data))
    }
    return io.MultiReader(r...)
}

If it's the same behaviour, the contract is being abused.

[Saxon Milton]

Let me clarify, the same code works when pushing to the cloud, but when I push to a local instance, it doesn't work. I haven't changed anything to do with the pins, this is the code that's been here for a while. For some reason, vidgrind/netreceiver thinks there is no request body. If I replace NewPayloadReader(pins) with bytes.NewReader(pins[0].Data) then it works for cloud and local instance, so for some reason, it doesn't like our PayloadReader - but only in the case of dev appserver (local instance). I can try to replace the code with what you've written when I get the chance. I'll send an email with instructions to reproduce.

[kortschak]

Sure. There are already known differences in how dev_appserver and real infrastructure work, so that data point is not really all that helpful in debugging this. At the moment, there is not enough information (I don't have the call site to look at e.g.) for me to be able to do anything other than guess. The best thing to do, would be dump the pins you are giving to NewPayloadReader using something like github.com/kortschak/utter and then we can play with what reading that collection looks like.

[Saxon Milton]

I have alot of other stuff to do - could I give you instructions to reproduce and you explore ?

[kortschak]

Given that you've been working with this and have the knowledge of the behaviour, it should take a few minutes to capture the data and confirm that the code above behaves the same way. It will take me much longer to get to deal with the issue and replicate it. I think it would be better for you to at least do the code snippet replacement and report back. If you can point to the code and invocation, I can have a look when I get a chance.

[Saxon Milton]

okay, using that code gives me the same problem. I get the following in the same window as where I run revid-cli: 2018/12/10 17:47:02 Unsolicited response received on idle HTTP channel starting with "HTTP/1.1 400 Bad Request\r\nContent-Length: 22\r\nContent-Type: text/plain\r\n\r\nMalformed Request-Line"; err=<nil>

and i get vidgrind giving me this: 2018/12/10 07:16:53 WARNING: Could not read Body: EOF 2018/12/10 07:16:53 DEBUG: {"V0":"105280","ma":"00:00:00:00:00:01"} INFO 2018-12-10 07:16:53,533 module.py:861] default: "POST /recv?vn=137&ma=00:00:00:00:00:01&dk=1&V0=105280 HTTP/1.1" 200 40 INFO 2018-12-10 07:16:53,582 module.py:861] default: "GET /poll?vn=137&ma=00:00:00:00:00:01&dk=1 HTTP/1.1" 302 24 INFO 2018-12-10 07:16:53,594 module.py:861] default: "GET / HTTP/1.1" 200 13 2018/12/10 07:16:54 WARNING: Could not read Body: EOF 2018/12/10 07:16:54 DEBUG: {"V0":"105280","ma":"00:00:00:00:00:01"} INFO 2018-12-10 07:16:54,216 module.py:861] default: "POST /recv?vn=137&ma=00:00:00:00:00:01&dk=1&V0=105280 HTTP/1.1" 200 40 2018/12/10 07:16:55 WARNING: Could not read Body: EOF 2018/12/10 07:16:55 DEBUG: {"V0":"105280","ma":"00:00:00:00:00:01"} INFO 2018-12-10 07:16:55,179 module.py:861] default: "POST /recv?vn=137&ma=00:00:00:00:00:01&dk=1&V0=105280 HTTP/1.1" 200 40 2018/12/10 07:16:55 WARNING: Could not read Body: EOF 2018/12/10 07:16:55 DEBUG: {"V0":"105280","ma":"00:00:00:00:00:01"} INFO 2018-12-10 07:16:55,779 module.py:861] default: "POST /recv?vn=137&ma=00:00:00:00:00:01&dk=1&V0=105280 HTTP/1.1" 200 40 2018/12/10 07:16:56 WARNING: Could not read Body: EOF 2018/12/10 07:16:56 DEBUG: {"V0":"105280","ma":"00:00:00:00:00:01"} INFO 2018-12-10 07:16:56,297 module.py:861] default: "POST /recv?vn=137&ma=00:00:00:00:00:01&dk=1&V0=105280 HTTP/1.1" 200 40 2018/12/10 07:16:56 WARNING: Could not read Body: EOF 2018/12/10 07:16:56 DEBUG: {"V0":"105280","ma":"00:00:00:00:00:01"} INFO 2018-12-10 07:16:56,901 module.py:861] default: "POST /recv?vn=137&ma=00:00:00:00:00:01&dk=1&V0=105280 HTTP/1.1" 200 40 INFO 2018-12-10 07:16:58,708 module.py:861] default: "GET /poll?vn=137&ma=00:00:00:00:00:01&dk=1 HTTP/1.1" 302 24 INFO 2018-12-10 07:16:58,716 module.py:861] default: "GET / HTTP/1.1" 200 13 2018/12/10 07:16:59 WARNING: Could not read Body: EOF 2018/12/10 07:16:59 DEBUG: {"V0":"105280","ma":"00:00:00:00:00:01"} INFO 2018-12-10 07:16:59,376 module.py:861] default: "POST /recv?vn=137&ma=00:00:00:00:00:01&dk=1&V0=105280 HTTP/1.1" 200 40 2018/12/10 07:17:01 WARNING: Could not read Body: EOF 2018/12/10 07:17:01 DEBUG: {"V0":"105280","ma":"00:00:00:00:00:01"} INFO 2018-12-10 07:17:01,697 module.py:861] default: "POST /recv?vn=137&ma=00:00:00:00:00:01&dk=1&V0=105280 HTTP/1.1" 200 40 2018/12/10 07:17:02 WARNING: Could not read Body: EOF 2018/12/10 07:17:02 DEBUG: {"V0":"105280","ma":"00:00:00:00:00:01"} INFO 2018-12-10 07:17:02,616 module.py:861] default: "POST /recv?vn=137&ma=00:00:00:00:00:01&dk=1&V0=105280 HTTP/1.1" 200 40

[Saxon Milton]

This needs to be fixed by the end of Friday at the latest - I have some other functionality I need to get done, so I'm wondering if a temp fix could just be to use bytes.NewReader(pins[pinWithData].Data), which should be fine considering we're currently ever only using one video pin for any one device?

[kortschak]

OK, so the fact that using io.MultiReader gives you the same problem says that this is not a problem with netsender.PayloadReader (the io.MultiReader could be used as a replacement for ours, but requires a slice allocation). The fact that only sending the first Pin succeeds suggests that the Pins that are being added to the PayloadReader are not correct in some way - this means that they need to be dumped to inspect them and perform some completely reproducible test analysis. Dumping some pins will really only take a few minutes and you can post here and I'll take it on from there.

You can just send the first pin if you want if you know that it's the only one with bin data. However, at the moment, I don't see a clear cause, and you say there is a difference between the dev server and appengine (which is consistent with other bugs we've had).

[Saxon Milton]

the pin has 105kB of data in it though, perhaps I can email it.

[kortschak]

Email me it to me.

[Saxon Milton]

Turns out the problem lies within dev_appserver. Therefore no changes are required to av.