Driver doesn't start #25

smacker · 2019-02-06T12:28:52Z

I use bblfshd v2.11.4 and csharp-driver v1.2.0.

To reproduce the bug I use this simple program:

package main

import (
	"context"
	"fmt"
	"time"

	bblfsh "gopkg.in/bblfsh/client-go.v3"
)

const code = `// A Hello World! program in C#.
using System;
namespace HelloWorld
{
    class Hello
    {
        static void Main()
        {
            Console.WriteLine("Hello World!");

            // Keep the console window open in debug mode.
            Console.WriteLine("Press any key to exit.");
            Console.ReadKey();
        }
    }
}`

func main() {
	client, err := bblfsh.NewClient("127.0.0.1:9432")
	if err != nil {
		panic(err)
	}

	go func() {
		started := time.Now()
		for {
			time.Sleep(time.Second)
			fmt.Println("Time since request started", time.Now().Sub(started))
		}
	}()

	_, _, err = client.
		NewParseRequest().
		Context(context.Background()).
		Language("csharp").
		Content(code).
		UAST()
	if err != nil {
		fmt.Println(err)
	}

	fmt.Println("success")
}

$ go run bblfsh_csharp.go
Time since request started 1.004217185s
...
Time since request started 5m3.852441925s

there are no logs on the server side except when I Ctrl-C the program:

[2019-02-06T12:27:00Z]  WARN unable to allocate a driver instance: context canceled language=csharp
[2019-02-06T12:27:00Z] ERROR request processed content 341 bytes error: context canceled elapsed=5m4.8500838s language=csharp

I see this processes in the container:

$ docker top 044c7dcebcc6
PID                 USER                TIME                COMMAND
3993                root                0:19                bblfshd
4061                root                0:00                bash
4178                root                0:00                /opt/driver/bin/driver --log-level info --log-format text --log-fields {"id":"01d31bjzsfzdahqx476ptgadrg","language":"csharp"} --network unix --address /tmp/rpc.sock
4195                root                0:00                sh /opt/driver/bin/native
4196                root                0:00                dotnet native.dll

The text was updated successfully, but these errors were encountered:

dennwc · 2019-02-06T12:32:35Z

May be related:
bblfsh/sdk#351
bblfsh/bblfshd#229

bzz · 2019-02-07T15:17:12Z

Could not reproduce it using only a csharp driver on linux:

docker run -it  -p 9432:9432 bblfsh/csharp-driver:v1.2.0 --log-level=debug

go get -v -u -f "gopkg.in/bblfsh/client-go.v3"
time go run bblfsh_csharp.go

success
real    0m1.706s
user    0m1.220s
sys     0m0.242s

Will try with bblfshd in between and post back.

Is there a chance you could try the above and post if that works for you, @smacker ?

smacker · 2019-02-07T15:26:43Z

With docker run -it -p 9432:9432 bblfsh/csharp-driver instead of bblfsh & driver install:

$ go run bblfsh_csharp.go
success

but with bblfsd it runs forever:

root@5032028635cb:/# bblfshctl status
+----------+----------------+---------------+---------+--------+
| LANGUAGE | SUCCESS/FAILED | STATE/DESIRED | WAITING | EXITED |
+----------+----------------+---------------+---------+--------+
| csharp   | 0/0            | 0/0           | 1       | 0      |
+----------+----------------+---------------+---------+--------+

bzz · 2019-02-07T15:29:03Z

Could not reproduce with bblfshd either

docker run -it --name bblfshd --privileged -p 9432:9432 bblfsh/bblfshd --log-level=debug 
docker exec -it bblfshd bblfshctl driver install --recommended

time go run bblfsh_csharp.go
Time since request started 1.000115931s
Time since request started 2.000400965s
success
real    0m4.489s
user    0m1.308s
sys     0m0.268s

bblfshd logs

[2019-02-07T15:25:52Z] DEBUG spawning driver instance "bblfsh/csharp-driver:latest" ...
[2019-02-07T15:25:52Z]  INFO csharp-driver version: v1.2.0 (build: 2019-02-05T20:10:17Z) id=01d3491ck8dd5nwm8wx0jfhzts language=csharp
[2019-02-07T15:25:52Z] DEBUG executing native binary ... id=01d3491ck8dd5nwm8wx0jfhzts language=csharp
[2019-02-07T15:25:52Z]  INFO server listening in /tmp/rpc.sock (unix) id=01d3491ck8dd5nwm8wx0jfhzts language=csharp
[2019-02-07T15:25:53Z]  INFO new driver instance started bblfsh/csharp-driver:latest (01d3491ck8dd5nwm8wx0jfhzts)
[2019-02-07T15:25:54Z] DEBUG request processed content 341 bytes elapsed=2.274346972s language=csharp

docker exec -it bblfshd bblfshctl status
+----------+----------------+---------------+---------+--------+
| LANGUAGE | SUCCESS/FAILED | STATE/DESIRED | WAITING | EXITED |
+----------+----------------+---------------+---------+--------+
| csharp   | 1/0            | 1/1           | 0       | 0      |
+----------+----------------+---------------+---------+--------+
Response time 6.808µs

@smacker Any chance you could enable debug logs on bblfshd and post those as well?

smacker · 2019-02-07T15:35:16Z

logs with debug enabled:

$ docker run -it --rm --privileged -p 9432:9432 bblfsh/bblfshd:v2.11.4-drivers --log-level=debug
[2019-02-07T15:32:18Z]  INFO bblfshd version: v2.11.4 (build: 2019-02-05T19:18:20+0000)
[2019-02-07T15:32:18Z]  INFO initializing runtime at /var/lib/bblfshd
[2019-02-07T15:32:18Z]  INFO server listening in 0.0.0.0:9432 (tcp)
[2019-02-07T15:32:18Z]  INFO control server listening in /var/run/bblfshctl.sock (unix)
[2019-02-07T15:32:39Z] DEBUG Looking for TLS certificates and private keys in /etc/docker/certs.d/docker.io
[2019-02-07T15:32:39Z] DEBUG Using registries.d directory /etc/containers/registries.d for sigstore configuration
[2019-02-07T15:32:39Z] DEBUG  No signature storage configuration found for docker.io/bblfsh/csharp-driver:latest
[2019-02-07T15:32:39Z] DEBUG GET https://registry-1.docker.io/v2/
[2019-02-07T15:32:40Z] DEBUG Ping https://registry-1.docker.io/v2/ err <nil>
[2019-02-07T15:32:40Z] DEBUG Ping https://registry-1.docker.io/v2/ status 401
[2019-02-07T15:32:40Z] DEBUG GET https://registry-1.docker.io/v2/bblfsh/csharp-driver/manifests/latest
[2019-02-07T15:32:41Z] DEBUG Downloading /v2/bblfsh/csharp-driver/blobs/sha256:197eba2ce7b2e8be3960959737c31de57274820033144fa95fd3d2111b281106
[2019-02-07T15:32:41Z] DEBUG GET https://registry-1.docker.io/v2/bblfsh/csharp-driver/blobs/sha256:197eba2ce7b2e8be3960959737c31de57274820033144fa95fd3d2111b281106
[2019-02-07T15:32:41Z] DEBUG Looking for TLS certificates and private keys in /etc/docker/certs.d/docker.io
[2019-02-07T15:32:41Z] DEBUG Using registries.d directory /etc/containers/registries.d for sigstore configuration
[2019-02-07T15:32:41Z] DEBUG  No signature storage configuration found for docker.io/bblfsh/csharp-driver:latest
[2019-02-07T15:32:41Z] DEBUG GET https://registry-1.docker.io/v2/
[2019-02-07T15:32:42Z] DEBUG Ping https://registry-1.docker.io/v2/ err <nil>
[2019-02-07T15:32:42Z] DEBUG Ping https://registry-1.docker.io/v2/ status 401
[2019-02-07T15:32:42Z] DEBUG GET https://registry-1.docker.io/v2/bblfsh/csharp-driver/manifests/latest
[2019-02-07T15:32:42Z] DEBUG Looking for TLS certificates and private keys in /etc/docker/certs.d/docker.io
[2019-02-07T15:32:42Z] DEBUG Using registries.d directory /etc/containers/registries.d for sigstore configuration
[2019-02-07T15:32:42Z] DEBUG  No signature storage configuration found for docker.io/bblfsh/csharp-driver:latest
[2019-02-07T15:32:42Z] DEBUG Downloading /v2/bblfsh/csharp-driver/blobs/sha256:5e6ec7f28fb77f84f64b8c29fcb0a746260563f5858315e3e9fcc4aee2844840
[2019-02-07T15:32:42Z] DEBUG GET https://registry-1.docker.io/v2/
[2019-02-07T15:32:43Z] DEBUG Ping https://registry-1.docker.io/v2/ err <nil>
[2019-02-07T15:32:43Z] DEBUG Ping https://registry-1.docker.io/v2/ status 401
[2019-02-07T15:32:43Z] DEBUG GET https://registry-1.docker.io/v2/bblfsh/csharp-driver/blobs/sha256:5e6ec7f28fb77f84f64b8c29fcb0a746260563f5858315e3e9fcc4aee2844840
[2019-02-07T15:32:46Z] DEBUG Downloading /v2/bblfsh/csharp-driver/blobs/sha256:3e4c3746d9614efa110a56ce94de215c1e13e7ae6bf796b9d05c8d2bbfc2e7a6
[2019-02-07T15:32:46Z] DEBUG GET https://registry-1.docker.io/v2/bblfsh/csharp-driver/blobs/sha256:3e4c3746d9614efa110a56ce94de215c1e13e7ae6bf796b9d05c8d2bbfc2e7a6
[2019-02-07T15:32:48Z] DEBUG Downloading /v2/bblfsh/csharp-driver/blobs/sha256:8b5cfece4dd895dbcb7dc043ad05760256de9d25b2cbe5e7672e2bbec892338f
[2019-02-07T15:32:48Z] DEBUG GET https://registry-1.docker.io/v2/bblfsh/csharp-driver/blobs/sha256:8b5cfece4dd895dbcb7dc043ad05760256de9d25b2cbe5e7672e2bbec892338f
[2019-02-07T15:32:49Z] DEBUG Downloading /v2/bblfsh/csharp-driver/blobs/sha256:a6050fb5051bf4843c6c39cdf3d84978af11bb548115a93c75f36f1ce916a524
[2019-02-07T15:32:49Z] DEBUG GET https://registry-1.docker.io/v2/bblfsh/csharp-driver/blobs/sha256:a6050fb5051bf4843c6c39cdf3d84978af11bb548115a93c75f36f1ce916a524
[2019-02-07T15:32:52Z] DEBUG Downloading /v2/bblfsh/csharp-driver/blobs/sha256:a25ffaae9a7e551b7cedb9e54d852d610432acbf849ae1770ea318fd51c3daba
[2019-02-07T15:32:52Z] DEBUG GET https://registry-1.docker.io/v2/bblfsh/csharp-driver/blobs/sha256:a25ffaae9a7e551b7cedb9e54d852d610432acbf849ae1770ea318fd51c3daba
[2019-02-07T15:32:53Z] DEBUG Downloading /v2/bblfsh/csharp-driver/blobs/sha256:5bddc34c6d824276b92bed98fdccdee0e9c4d99b44ec3789245b9e3bb18fa0f0
[2019-02-07T15:32:53Z] DEBUG GET https://registry-1.docker.io/v2/bblfsh/csharp-driver/blobs/sha256:5bddc34c6d824276b92bed98fdccdee0e9c4d99b44ec3789245b9e3bb18fa0f0
[2019-02-07T15:32:53Z] DEBUG Downloading /v2/bblfsh/csharp-driver/blobs/sha256:4bc3bbd1ab51c04fcc2c6d3758a3757221baa944855518407a2f0361119d42a4
[2019-02-07T15:32:53Z] DEBUG GET https://registry-1.docker.io/v2/bblfsh/csharp-driver/blobs/sha256:4bc3bbd1ab51c04fcc2c6d3758a3757221baa944855518407a2f0361119d42a4
[2019-02-07T15:32:54Z] DEBUG Downloading /v2/bblfsh/csharp-driver/blobs/sha256:08399b1d360e124f667ae0b1e92f2351bf2de8c1c96efb07a8a76b32c4b61fe5
[2019-02-07T15:32:54Z] DEBUG GET https://registry-1.docker.io/v2/bblfsh/csharp-driver/blobs/sha256:08399b1d360e124f667ae0b1e92f2351bf2de8c1c96efb07a8a76b32c4b61fe5
[2019-02-07T15:32:55Z] DEBUG Downloading /v2/bblfsh/csharp-driver/blobs/sha256:eae98733239e0f618c91d5f05a3568494375a4ffacfc610f1ae29a44bb0568e2
[2019-02-07T15:32:55Z] DEBUG GET https://registry-1.docker.io/v2/bblfsh/csharp-driver/blobs/sha256:eae98733239e0f618c91d5f05a3568494375a4ffacfc610f1ae29a44bb0568e2
[2019-02-07T15:32:56Z] DEBUG Downloading /v2/bblfsh/csharp-driver/blobs/sha256:e757fc8ca18d749bf59b2358657619fdfcbac2d069d4d1e4f187f72150dd8e90
[2019-02-07T15:32:56Z] DEBUG GET https://registry-1.docker.io/v2/bblfsh/csharp-driver/blobs/sha256:e757fc8ca18d749bf59b2358657619fdfcbac2d069d4d1e4f187f72150dd8e90
[2019-02-07T15:32:57Z] DEBUG Downloading /v2/bblfsh/csharp-driver/blobs/sha256:44f91520eb0ceab61fd829a3cfff1003c11c41a7c77bf38888507240de3d00eb
[2019-02-07T15:32:57Z] DEBUG GET https://registry-1.docker.io/v2/bblfsh/csharp-driver/blobs/sha256:44f91520eb0ceab61fd829a3cfff1003c11c41a7c77bf38888507240de3d00eb
[2019-02-07T15:32:57Z] DEBUG Downloading /v2/bblfsh/csharp-driver/blobs/sha256:83faf40b48948dca00999e1408441a136a13910a9f4ffd85d571b773c4ac009f
[2019-02-07T15:32:57Z] DEBUG GET https://registry-1.docker.io/v2/bblfsh/csharp-driver/blobs/sha256:83faf40b48948dca00999e1408441a136a13910a9f4ffd85d571b773c4ac009f
[2019-02-07T15:32:58Z] DEBUG Downloading /v2/bblfsh/csharp-driver/blobs/sha256:197eba2ce7b2e8be3960959737c31de57274820033144fa95fd3d2111b281106
[2019-02-07T15:32:58Z] DEBUG GET https://registry-1.docker.io/v2/bblfsh/csharp-driver/blobs/sha256:197eba2ce7b2e8be3960959737c31de57274820033144fa95fd3d2111b281106
[2019-02-07T15:32:58Z]  INFO driver csharp installed "bblfsh/csharp-driver:latest"
[2019-02-07T15:33:11Z] DEBUG spawning driver instance "bblfsh/csharp-driver:latest" ...
[2019-02-07T15:33:17Z] ERROR error selecting pool: unexpected error: context deadline exceeded
[2019-02-07T15:33:17Z] ERROR request processed content 341 bytes error: unexpected error: context deadline exceeded elapsed=5.2317872s language=csharp
[2019-02-07T15:33:17Z]  INFO csharp-driver version: v1.2.0 (build: 2019-02-05T20:10:17Z) id=01d349esjkym13zk3w9xg7dh5h language=csharp
[2019-02-07T15:33:17Z] DEBUG executing native binary ... id=01d349esjkym13zk3w9xg7dh5h language=csharp
[2019-02-07T15:33:17Z]  INFO server listening in /tmp/rpc.sock (unix) id=01d349esjkym13zk3w9xg7dh5h language=csharp
[2019-02-07T15:33:42Z]  WARN unable to allocate a driver instance: context canceled language=csharp
[2019-02-07T15:33:42Z] ERROR request processed content 341 bytes error: context canceled elapsed=21.7611486s language=csharp

$ docker exec -it 27ee27dd9982 bblfshctl driver install --recommended
<installed>

$ go run bblfsh_csharp.go
Time since request started 1.003635328s
Time since request started 2.004506107s
Time since request started 3.008450937s
Time since request started 4.010999181s
Time since request started 5.016118617s
rpc error: code = Unknown desc = unexpected error: context deadline exceeded
success
smacker in ~/tmp
$ go run bblfsh_csharp.go
Time since request started 1.00328464s
Time since request started 2.003956785s
Time since request started 3.004182579s
Time since request started 4.008334441s
Time since request started 5.011290157s
Time since request started 6.01355509s
Time since request started 7.014369933s
Time since request started 8.016775843s
Time since request started 9.020239314s
Time since request started 10.024268513s
<runs forever>

bzz · 2019-02-07T15:54:49Z

@smacker this is definitely the case of requests arriving too early, before the driver has started.
AFAIK it is planned to be addressed in bblfsh/sdk#351 and as @dennwc mentioned elsewhere, might require some work.

Although this does not explain why subsequent request do not succeed after the driver has already started on the first one.. do they?

Sorry for bothering, but as soon as it's not reproducible for me it's hard to check - could you post only the last part of debug logs after 2 subsequent runs of go run ..., after a several seconds interval?

smacker · 2019-02-07T16:16:36Z

There is no logs in bblfshd since the moment I start my script to the moment I stop it. Only when it stopped I see:

[2019-02-07T16:15:56Z]  WARN unable to allocate a driver instance: context canceled language=csharp
[2019-02-07T16:15:56Z] ERROR request processed content 341 bytes error: context canceled elapsed=38.3382081s language=csharp

This behaviour is consistent no matter how many times I try.

bzz · 2019-02-12T11:46:01Z

Could partially reproduce this on macOS

docker run -d --rm --name bblfshd --privileged -p 9432:9432 bblfsh/bblfshd --log-level=debug
docker exec -it bblfshd bblfshctl driver install csharp bblfsh/csharp-driver:v1.3.0

time go run bblfsh_csharp.go                                                                                                            
Time since request started 1.000498362s
Time since request started 2.005853312s
Time since request started 3.0099585s
Time since request started 4.013441831s
Time since request started 5.017238517s
rpc error: code = Unknown desc = unexpected error: context deadline exceeded
success
go run bblfsh_csharp.go  1.00s user 0.34s system 21% cpu 6.171 total

with logs

time="2019-02-12T11:43:50Z" level=info msg="driver csharp installed "bblfsh/csharp-driver:v1.3.0""
time="2019-02-12T11:44:01Z" level=debug msg="spawning driver instance "bblfsh/csharp-driver:v1.3.0" ..."
time="2019-02-12T11:44:07Z" level=error msg="error selecting pool: unexpected error: context deadline exceeded"
time="2019-02-12T11:44:07Z" level=error msg="request processed content 341 bytes error: unexpected error: context deadline exceeded" elapsed=5.1687335s language=csharp
time="2019-02-12T11:44:07Z" level=info msg="csharp-driver version: v1.3.0 (build: 2019-02-11T13:40:55Z)" id=01d3grarv7mn9bs9me042jjyqq language=csharp
time="2019-02-12T11:44:07Z" level=debug msg="executing native binary ..." id=01d3grarv7mn9bs9me042jjyqq language=csharp
time="2019-02-12T11:44:07Z" level=info msg="server listening in /tmp/rpc.sock (unix)" id=01d3grarv7mn9bs9me042jjyqq language=csharp

and status

docker exec -it bblfshd bblfshctl status
+----------+----------------+---------------+---------+--------+
| LANGUAGE | SUCCESS/FAILED | STATE/DESIRED | WAITING | EXITED |
+----------+----------------+---------------+---------+--------+
| csharp   | 0/0            | 0/0           | 0       | 0      |
+----------+----------------+---------------+---------+--------+

Next 2 run failed in exactly the way described above

docker exec -it bblfshd bblfshctl status
+----------+----------------+---------------+---------+--------+
| LANGUAGE | SUCCESS/FAILED | STATE/DESIRED | WAITING | EXITED |
+----------+----------------+---------------+---------+--------+
| csharp   | 0/2            | 0/0           | 0       | 0      |
+----------+----------------+---------------+---------+--------+
Response time 12.2µs

with logs, after Ctrl-C


time="2019-02-12T11:54:00Z" level=warning msg="unable to allocate a driver instance: context canceled" language=csharp
time="2019-02-12T11:54:00Z" level=error msg="request processed content 341 bytes error: context canceled" elapsed=23.3003025s language=csharp

time="2019-02-12T11:55:29Z" level=warning msg="unable to allocate a driver instance: context canceled" language=csharp
time="2019-02-12T11:55:29Z" level=error msg="request processed content 341 bytes error: context canceled" elapsed=35.4790686s language=csharp

dennwc · 2019-02-12T17:20:08Z

Turned out to not be C#-related. See bblfsh/bblfshd#250.

dennwc · 2019-02-13T16:15:25Z

@smacker Can you please check it with the latest bblfshd release (v2.11.7)?

bzz · 2019-02-13T16:33:43Z

Confirmed, :latest bblfshd is able to parse C# on macOS 👏

smacker · 2019-02-13T16:38:31Z

$ go run bblfsh_csharp.go
Time since request started 1.00466997s
Time since request started 2.006313249s
Time since request started 3.006732205s
Time since request started 4.009675228s
Time since request started 5.013291032s
Time since request started 6.015359102s
success

🎉

dennwc · 2019-02-13T16:42:40Z

Still, need to figure out why it takes exactly 6 sec sometimes. But I'll close this one since it was resolved.

smacker mentioned this issue Feb 6, 2019

Deadline exceeded when drivers cannot be allocated (even if the client provides context.Background()) bblfsh/bblfshd#229

Closed

dennwc added the bug Something isn't working label Feb 6, 2019

smacker mentioned this issue Feb 6, 2019

Context deadline exceeded parsing csharp bblfsh/go-client#107

Closed

dennwc self-assigned this Feb 12, 2019

dennwc mentioned this issue Feb 12, 2019

Fix multiple issues with a driver pool bblfsh/bblfshd#250

Merged

dennwc closed this as completed Feb 13, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Driver doesn't start #25

Driver doesn't start #25

smacker commented Feb 6, 2019

dennwc commented Feb 6, 2019

bzz commented Feb 7, 2019 •

edited

Loading

smacker commented Feb 7, 2019

bzz commented Feb 7, 2019 •

edited

Loading

smacker commented Feb 7, 2019

bzz commented Feb 7, 2019

smacker commented Feb 7, 2019

bzz commented Feb 12, 2019 •

edited

Loading

dennwc commented Feb 12, 2019

dennwc commented Feb 13, 2019

bzz commented Feb 13, 2019

smacker commented Feb 13, 2019

dennwc commented Feb 13, 2019

Driver doesn't start #25

Driver doesn't start #25

Comments

smacker commented Feb 6, 2019

dennwc commented Feb 6, 2019

bzz commented Feb 7, 2019 • edited Loading

smacker commented Feb 7, 2019

bzz commented Feb 7, 2019 • edited Loading

smacker commented Feb 7, 2019

bzz commented Feb 7, 2019

smacker commented Feb 7, 2019

bzz commented Feb 12, 2019 • edited Loading

dennwc commented Feb 12, 2019

dennwc commented Feb 13, 2019

bzz commented Feb 13, 2019

smacker commented Feb 13, 2019

dennwc commented Feb 13, 2019

bzz commented Feb 7, 2019 •

edited

Loading

bzz commented Feb 7, 2019 •

edited

Loading

bzz commented Feb 12, 2019 •

edited

Loading