Beeps are heard when importing scheme to v20.11.0

Issues Dgraph
,
1

Report a Dgraph Bug

What version of Dgraph are you using?

v.20.11.0 (docker)

Have you tried reproducing the issue with the latest release?

Yes

What is the hardware spec (RAM, OS)?

Dev station with Linux Fedora and 32GB RAM

UPDATE → Also tested on local Ubuntu linux server running the same docker. Connecting from Mac stock terminal to shell running tmux.

Steps to reproduce the issue (command/config used to run Dgraph).

Drop scheme:

curl --request POST \
  --url http://127.0.0.1:8080/alter \
  --header 'content-type: application/json' \
  --data '{
	"drop_all": true
}'

create scheme:

curl --request POST \
  --url 'http://127.0.0.1:8080/alter?runInBackground=true' \
  --data '<appv.id>: string @index(hash) @upsert .
<appv.conf>: string .
<appv.at>: datetime .

appv.app: uid @reverse .
appv.type: [uid] .

type AppVer {
    appv.id
    appv.conf
    appv.at
    appv.app
    appv.type
}'

Expected behavior and actual result.

Expecting:

Finish silently

Actual

Console bip with message:

dg-alpha | I1218 13:53:39.567513      18 http.go:586] Got alter request via HTTP from 172.22.0.1:44214
dg-alpha | I1218 13:53:39.567562      18 server.go:324] Received ALTER op: drop_all:true 
dg-alpha | I1218 13:53:39.567580      18 server.go:1376] Got Alter request from: "172.22.0.1:44214"
dg-alpha | I1218 13:53:39.568263      18 log.go:34] DropAll called. Blocking writes...
dg-alpha | I1218 13:53:39.568286      18 log.go:34] Writes flushed. Stopping compactions now...
dg-alpha | I1218 13:53:39.580562      18 log.go:34] Deleted 1 SSTables. Now deleting value logs...
dg-alpha | I1218 13:53:39.580635      18 log.go:34] Value logs deleted. Creating value log file: 1
dg-alpha | I1218 13:53:39.580751      18 log.go:34] Deleted 1 value log files. DropAll done.
dg-alpha | I1218 13:53:39.582055      18 log.go:34] Resuming writes
dg-alpha | I1218 13:53:39.584961      18 access_ee.go:389] ResetAcl closed
dg-alpha | I1218 13:53:39.585612      18 admin.go:510] Updating GraphQL schema from subscription.
dg-alpha | I1218 13:53:39.585628      18 admin.go:539] Skipping GraphQL schema update as the new schema is the same as the current schema.
dg-alpha | I1218 13:53:39.586418      18 graphql.go:39] ResetCors closed
dg-alpha | I1218 13:53:39.586429      18 server.go:361] ALTER op: drop_all:true  done
dg-alpha | I1218 13:53:39.861004      18 run.go:819] Updating cors from subscription.
dg-alpha | I1218 13:53:39.861019      18 run.go:843] Updating cors origins: [*]
dg-alpha | I1218 13:53:50.649834      18 http.go:586] Got alter request via HTTP from 172.22.0.1:44308
dg-alpha | I1218 13:53:50.649888      18 server.go:324] Received ALTER op: schema:"<appv.id>: string @index(hash) @upsert .\n<appv.conf>: string .\n<appv.at>: datetime .\n\nappv.app: uid @reverse .\nappv.type: [uid] .\n\ntype AppVer {\n    appv.id\n    appv.conf\n    appv.at\n    appv.app\n    appv.type\n}" run_in_background:true 
dg-alpha | I1218 13:53:50.649901      18 server.go:1376] Got Alter request from: "172.22.0.1:44308"
dg-alpha | I1218 13:53:50.650341      18 server.go:462] Got schema: &{Preds:[predicate:"appv.id" value_type:STRING directive:INDEX tokenizer:"hash" upsert:true  predicate:"appv.conf" value_type:STRING  predicate:"appv.at" value_type:DATETIME  predicate:"appv.app" value_type:UID directive:REVERSE  predicate:"appv.type" value_type:UID list:true ] Types:[type_name:"AppVer" fields:<predicate:"appv.id" > fields:<predicate:"appv.conf" > fields:<predicate:"appv.at" > fields:<predicate:"appv.app" > fields:<predicate:"appv.type" > ]}
dg-alpha | I1218 13:53:50.650528      18 draft.go:180] Operation started with id: opIndexing
dg-alpha | I1218 13:53:50.650552      18 index.go:889] Computing prefix index for attr appv.id and tokenizers []
dg-alpha | I1218 13:53:50.650559      18 index.go:907] Deleting index for attr appv.id and tokenizers [hash]
dg-alpha | I1218 13:53:50.650570      18 index.go:779] Deleting indexes for appv.id
dg-alpha | I1218 13:53:50.650576      18 log.go:34] DropPrefix called for [appv.id
                                                                                   appv.id
                                                                                          ]
dg-alpha | I1218 13:53:50.650588      18 log.go:34] Writes flushed. Stopping compactions now...
dg-alpha | I1218 13:53:50.650706      18 draft.go:124] Operation completed with id: opRollup
dg-alpha | I1218 13:53:50.688204      18 log.go:34] DropPrefix done
dg-alpha | I1218 13:53:50.688223      18 log.go:34] Resuming writes
dg-alpha | I1218 13:53:50.688261      18 index.go:779] Deleting indexes for appv.conf
dg-alpha | I1218 13:53:50.688333      18 index.go:779] Deleting indexes for appv.at
dg-alpha | I1218 13:53:50.688376      18 index.go:779] Deleting indexes for appv.app
dg-alpha | I1218 13:53:50.688382      18 log.go:34] DropPrefix called for appv.appappv.app]
dg-alpha | I1218 13:53:50.688392      18 log.go:34] Writes flushed. Stopping compactions now...
dg-alpha | I1218 13:53:50.711621      18 log.go:34] DropPrefix done
dg-alpha | I1218 13:53:50.711640      18 log.go:34] Resuming writes
dg-alpha | I1218 13:53:50.711681      18 index.go:779] Deleting indexes for appv.type
dg-alpha | I1218 13:53:50.743662      18 log.go:34] Rebuilding index for predicate appv.type (1/2): Sent data of size 0 B
dg-alpha | I1218 13:53:50.751722      18 index.go:942] Rebuilding index for attr appv.id and tokenizers [hash]
dg-alpha | I1218 13:53:50.751725      18 index.go:1131] Rebuilding reverse index for appv.app
dg-alpha | I1218 13:53:50.751770      18 server.go:476] ALTER op: schema:"<appv.id>: string @index(hash) @upsert .\n<appv.conf>: string .\n<appv.at>: datetime .\n\nappv.app: uid @reverse .\nappv.type: [uid] .\n\ntype AppVer {\n    appv.id\n    appv.conf\n    appv.at\n    appv.app\n    appv.type\n}" run_in_background:true  done
dg-alpha | I1218 13:53:50.780893      18 log.go:34] Rebuilding index for predicate appv.id (1/2): Sent data of size 0 B
dg-alpha | I1218 13:53:50.805102      18 log.go:34] Rebuilding index for predicate appv.app (1/2): Sent data of size 0 B
dg-alpha | I1218 13:53:50.811866      18 mutation.go:188] Done schema update predicate:"appv.id" value_type:STRING directive:INDEX tokenizer:"hash" upsert:true 
dg-alpha | I1218 13:53:50.824567      18 mutation.go:188] Done schema update predicate:"appv.app" value_type:UID directive:REVERSE 
dg-alpha | I1218 13:53:50.824621      18 draft.go:124] Operation completed with id: opIndexing
dg-alpha | I1218 13:54:00.824790      18 draft.go:180] Operation started with id: opRollup

Not sure if something is wrong. Tested queries worked as expected.
When issuing bigger scheme I hear even more bips.

2

Dgraph is started with docker-compose

version: "3.2"
services:
  zero:
    container_name: dg-zero
    image: dgraph/dgraph:v20.11.0
    volumes:
      - $PWD/data:/dgraph
    ports:
      - 5080:5080
      - 6080:6080
    restart: on-failure
    command: dgraph zero --my=zero:5080
  alpha:
    container_name: dg-alpha
    image: dgraph/dgraph:v20.11.0
    volumes:
      - $PWD/data:/dgraph
      - /tmp:/host
    ports:
      - 8080:8080
      - 9080:9080
      - 7080:7080
    restart: on-failure
    command: dgraph alpha --my=server:7080 --lru_mb=2048 --zero=zero:5080 --my=alpha:7080 --whitelist 172.0.0.0/8
  ratel:
    container_name: dg-ratel
    image: dgraph/dgraph:v20.11.0
    ports:
      - 8000:8000
    command: dgraph-ratel
3

Your logs seems alright, what are your concerns?

4

The beeps of course. It hint that something might be wrong. A flowless procedure should be quiet.

As a customer I dont have the tools to confirm if its only a special char returned to the console or some kind of error.

Same request to v20.7.* yield no beep.

5

Added to the dsecription:

6

Hum, a lot of things has changed in 20.11.0 - So you can expect different behavior.
Dgraph can’t finish silently after a drop all, a new schema request and operations. It is trying to rearrange the new schema and balance it. It will always throw those logs during this background tasks.

Only panic logs are important. The other are there just to have a notion of what is happening.

If you see a bad behavior using Dgraph, even without critical logs. Then you can be concern and flag us.

7

Of course. But beeps (sound) mean something else. My gues is that some kind of special char (maybe tab) is returned and that trigger the beep.

8

Can you check your output for a \a (or \x07 or \u0007) ?

9

When I send the full scheme I hear around 5 beeps. All repeat this pattern of gap/new line in the log:

dg-alpha | I1218 13:53:50.650570      18 index.go:779] Deleting indexes for appv.id
dg-alpha | I1218 13:53:50.650576      18 log.go:34] DropPrefix called for [appv.id
                                                                                   appv.id
                                                                                          ]
dg-alpha | I1218 13:53:50.650588      18 log.go:34] Writes flushed. Stopping compactions now...
dg-alpha | I1218 13:53:50.650706      18 draft.go:124] Operation completed with id: opRollup
dg-alpha | I1218 13:53:50.688204      18 log.go:34] DropPrefix done

Does that help?