tests: Enable verbose http2

[sergiocazzolato]

This is to have extra information about the protocol error downloading snaps

[mvo5]

The log has the protocol error for frame 0xc4204fbce0, I grepped for all logs with this frame and got the following:

$ grep  0xc4204fbce0 log.txt 
Aug 09 20:03:16 aug091949-909109 snapd[7255]: 2019/08/09 20:03:16 http2: Framer 0xc4204fbce0: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
Aug 09 20:03:16 aug091949-909109 snapd[7255]: 2019/08/09 20:03:16 http2: Framer 0xc4204fbce0: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
Aug 09 20:03:16 aug091949-909109 snapd[7255]: 2019/08/09 20:03:16 http2: Framer 0xc4204fbce0: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=869
Aug 09 20:03:16 aug091949-909109 snapd[7255]: 2019/08/09 20:03:16 http2: Framer 0xc4204fbce0: read SETTINGS len=6, settings: MAX_CONCURRENT_STREAMS=100
Aug 09 20:03:16 aug091949-909109 snapd[7255]: 2019/08/09 20:03:16 http2: Framer 0xc4204fbce0: wrote SETTINGS flags=ACK len=0
Aug 09 20:03:16 aug091949-909109 snapd[7255]: 2019/08/09 20:03:16 http2: Framer 0xc4204fbce0: read WINDOW_UPDATE len=4 (conn) incr=16711681
Aug 09 20:03:16 aug091949-909109 snapd[7255]: 2019/08/09 20:03:16 http2: Framer 0xc4204fbce0: read SETTINGS flags=ACK len=0
Aug 09 20:03:16 aug091949-909109 snapd[7255]: 2019/08/09 20:03:16 http2: Framer 0xc4204fbce0: read HEADERS flags=END_HEADERS stream=1 len=378
Aug 09 20:03:16 aug091949-909109 snapd[7255]: 2019/08/09 20:03:16 http2: Framer 0xc4204fbce0: read RST_STREAM stream=1 len=4 ErrCode=PROTOCOL_ERROR
Aug 09 20:03:16 aug091949-909109 snapd[7255]: 2019/08/09 20:03:16 http2: Framer 0xc4204fbce0: wrote RST_STREAM stream=1 len=4 ErrCode=CANCEL

the last few lines look a lot like golang/go#29125 - this bug is stale upstream and it seems the workaround might be to "just" retry but this is of course not great, would be nice to know why we get the RST_STREAM (which seems to come from the store end AFAICT?).

[mvo5]

Looking a bit more it seems like we get the PROCOTOL_ERROR from the remote side which appears to be fastly in this case:

Aug 09 20:03:16 aug091949-909109 snapd[7255]: 2019/08/09 20:03:16 http2: Transport failed to get client conn for fastly.cdn.snapcraft.io:443: http2: no cached connection was available
Aug 09 20:03:16 aug091949-909109 snapd[7255]: 2019/08/09 20:03:16 http2: Transport creating client conn 0xc4200baa80 to 151.101.250.217:443
...

[mvo5]

How that #7231 is merged I think we can close this one. Please reopen if I was too quick closing it :)