Non-persistent behavior on logging bblfsh parse errors

lwsanty commented 5 years ago

Having test in bblfsh-mockups regression suite One of it's sub-cases uses bblfsh mockup that returns such response

&v2.ParseResponse{Language: "go", Uast: bufData, Errors: nil},

where bufData = getUASTBytes("a")

func getUASTBytes(text string) ([]byte, error) {
    node := nodes.String(text)
    buf := bytes.NewBuffer(nil)
    if err := nodesproto.WriteTo(buf, node); err != nil {
        return nil, err
    }
    return buf.Bytes(), nil
}

expected gitbase output

time="2019-08-23T11:44:03+03:00" level=info msg="server started and listening on localhost:3306"
time="2019-08-23T11:44:04+03:00" level=info msg="NewConnection: client 1"
time="2019-08-23T11:44:04+03:00" level=info msg="audit trail" action=authentication address="127.0.0.1:58320" success=true system=audit user=root
time="2019-08-23T11:44:04+03:00" level=info msg="audit trail" action=authorization address="127.0.0.1:58320" connection_id=1 permission=read pid=1 query="select file_path, uast(blob_content) name \nfrom refs natural \njoin commit_files natural \njoin blobs \nwhere LANGUAGE(file_path) = 'Go' \nlimit 10" success=true system=audit user=root
time="2019-08-23T11:44:04+03:00" level=warning msg="unable to parse the given blob using bblfsh: rpc error: code = Canceled desc = context canceled"
time="2019-08-23T11:44:04+03:00" level=info msg="audit trail" action=query address="127.0.0.1:58320" connection_id=1 duration=40.864078ms pid=1 query="select file_path, uast(blob_content) name \nfrom refs natural \njoin commit_files natural \njoin blobs \nwhere LANGUAGE(file_path) = 'Go' \nlimit 10" success=true system=audit user=root
time="2019-08-23T11:44:04+03:00" level=info msg="ConnectionClosed: client 1"

the most crucial line to assert is

time="2019-08-23T11:44:04+03:00" level=warning msg="unable to parse the given blob using bblfsh: rpc error: code = Canceled desc = context canceled"

observed in 20% of this test runs the output does not contain parse error line

time="2019-08-23T11:44:11+03:00" level=info msg="server started and listening on localhost:3306"
time="2019-08-23T11:44:12+03:00" level=info msg="NewConnection: client 1"
time="2019-08-23T11:44:12+03:00" level=info msg="audit trail" action=authentication address="127.0.0.1:58326" success=true system=audit user=root
time="2019-08-23T11:44:12+03:00" level=info msg="audit trail" action=authorization address="127.0.0.1:58326" connection_id=1 permission=read pid=1 query="select file_path, uast(blob_content) name \nfrom refs natural \njoin commit_files natural \njoin blobs \nwhere LANGUAGE(file_path) = 'Go' \nlimit 10" success=true system=audit user=root
time="2019-08-23T11:44:12+03:00" level=info msg="audit trail" action=query address="127.0.0.1:58326" connection_id=1 duration=48.694585ms pid=1 query="select file_path, uast(blob_content) name \nfrom refs natural \njoin commit_files natural \njoin blobs \nwhere LANGUAGE(file_path) = 'Go' \nlimit 10" success=true system=audit user=root
time="2019-08-23T11:44:12+03:00" level=info msg="ConnectionClosed: client 1"

note test uses stdout+stderr capturer and at first it may be a delusion that capturer does not have time to capture this part of log, but it's not true, because: 1) I have checked this test with different pre-delays(0.5-5 seconds) before capture 2) imo this warning should appear during the query execution and afaik if ConnectionClosed: client 1 has appeared no additional query-related logs will be observed

erizocosmico commented 5 years ago

Warn should be printed if it's a blob parse error: https://github.com/src-d/gitbase/blob/000ef21ab45467f159ce5e2362df1a701790764e/internal/function/uast_utils.go#L124

erizocosmico commented 4 years ago

I've managed to reproduce this, but after much investigation I have no idea why this is happening, since the log is there. If anyone else wants to give this a try, feel free.

agarciamontoro commented 4 years ago

I spent the day yesterday with this and no clue either. Could it be possible that the error comes from some weird race condition when capturing the output, @lwsanty? I'm just throwing ideas here...