Dgraph Alpha logs say types are being deleted

[danielmai]

What version of Dgraph are you using?

master (68512e3)

Dgraph version   : v1.1.1-27-g68512e309
Dgraph SHA-256   : ba3efd0bdf97e6e2cd8a4fb275b4333d4fd0632db8ad85e0b41dfe828db343bf
Commit SHA-1     : 68512e309
Commit timestamp : 2019-12-26 09:29:02 -0800
Branch           : master
Go version       : go1.13.5

Have you tried reproducing the issue with the latest release?

v1.1.1.

What is the hardware spec (RAM, OS)?

Ubuntu Linux

1. Run Dgraph cluster.

2. Set a schema with types:

   name: string .
   
   type Person {
     name
   }
   
   type Item {
     name
   }
   

3. When a rollup happens, the Dgraph Alpha logs show that the types are being deleted.

   I1226 18:09:06.093199       1 log.go:34] Rolling up Created batch of size: 9.9 kB in 677.698µs.
   I1226 18:09:06.093228       1 log.go:34] Rolling up Sent 100 keys
   I1226 18:09:06.104548       1 draft.go:1080] Rolled up 100 keys. Done
   I1226 18:09:06.104574       1 draft.go:429] List rollup at Ts 114676: OK.
   I1226 18:09:06.129962       1 predicate_move.go:194] Was instructed to delete tablet: Person
   I1226 18:09:06.138919       1 index.go:996] Dropping predicate: [Person]
   I1226 18:09:06.138961       1 log.go:34] Writes flushed. Stopping compactions now...
   I1226 18:09:06.987475       1 log.go:34] Got compaction priority: {level:0score:1.74 dropPrefix:[0 0 6 80 101 114 115 111 110]}
   I1226 18:09:06.987607       1 log.go:34] Running for level: 0
   I1226 18:09:07.279167       1 log.go:34] LOG Compact 0->1, del 1 tables, add 1 tables, took 291.521482ms
   I1226 18:09:07.279250       1 log.go:34] Compaction for level: 0 DONE
   I1226 18:09:07.279307       1 log.go:34] DropPrefix done
   I1226 18:09:07.279359       1 log.go:34] Resuming writes
   I1226 18:09:07.279387       1 schema.go:79] Deleting schema for predicate: [Person]
   I1226 18:09:07.282437       1 predicate_move.go:194] Was instructed to delete tablet: Item
   I1226 18:09:07.287037       1 draft.go:387] Creating snapshot at index: 88672. ReadTs: 159598.
   I1226 18:09:07.287069       1 storage.go:589] CreateSnapshot i=88672, cs=nodes:1
   I1226 18:09:07.449441       1 index.go:996] Dropping predicate: [Item]
   I1226 18:09:07.449476       1 log.go:34] Writes flushed. Stopping compactions now...
   I1226 18:09:07.465005       1 log.go:34] Got compaction priority: {level:0 score:1.74 dropPrefix:[0 0 4 73 116 101 109]}
   I1226 18:09:07.465067       1 log.go:34] Running for level: 0
   I1226 18:09:07.728093       1 log.go:34] LOG Compact 0->1, del 2 tables, add 1 tables, took 262.995415ms
   I1226 18:09:07.728150       1 log.go:34] Compaction for level: 0 DONE
   I1226 18:09:07.728186       1 log.go:34] DropPrefix done
   I1226 18:09:07.728208       1 log.go:34] Resuming writes
   I1226 18:09:07.728229       1 schema.go:79] Deleting schema for predicate: [Item]
   I1226 18:09:07.729354       1 draft.go:1113] Sent tablet size update to Zero. Total size: 13 kB
   

   I don't expect any types to be deleted.

4. Even though these logs show up, the types are in schema are still present.

   schema {}
   

   ...
           "types": [
               {
                   "fields": [
                       {
                           "name": "name"
                       }
                   ],
                   "name": "Item"
               },
               {
                   "fields": [
                       {
                           "name": "name"
                       }
                   ],
                   "name": "Person"
               }
           ]
   ...
   

Expected behaviour and actual result

I don't expect to see these logs.

1. I never requested a delete, so the logs shouldn't say these are being deleted.
2. The logs say that the predicate/tablet is being deleted, but these are types in the schema.

In a cluster actively serving queries and mutations, these deletes can cause writes to be blocked for a few seconds. The logs below show the "Writes are blocked" logs for a total of 4-5 seconds.

I1224 09:59:00.935358       1 index.go:1000] Dropping predicate: [Person]
E1224 09:59:00.935424       1 writer.go:49] TxnWriter got error during callback: Writes are blocked, possibly due to DropAll or Close
E1224 09:59:00.935448       1 writer.go:49] TxnWriter got error during callback: Writes are blocked, possibly due to DropAll or Close
E1224 09:59:00.935476       1 writer.go:49] TxnWriter got error during callback: Writes are blocked, possibly due to DropAll or Close
E1224 09:59:00.935492       1 writer.go:49] TxnWriter got error during callback: Writes are blocked, possibly due to DropAll or Close
<log repeats 500,000+ times>
E1224 09:59:04.911084       1 writer.go:49] TxnWriter got error during callback: Writes are blocked, possibly due to DropAll or Close
I1224 09:59:05.170622       1 log.go:34] Rolling up Time elapsed: 25s, bytes sent: 287 MB, speed: 12 MB/sec
I1224 09:59:05.710485       1 log.go:34] LOG Compact 0->1, del 7 tables, add 4 tables, took 4.202887635s
I1224 09:59:05.710532       1 log.go:34] Compaction for level: 0 DONE
I1224 09:59:06.012297       1 log.go:34] Rolling up Time elapsed: 26s, bytes sent: 287 MB, speed: 11 MB/sec
I1224 09:59:06.347828       1 log.go:34] LOG Compact 1->1, del 1 tables, add 1 tables, took 637.240766ms
I1224 09:59:06.347858       1 log.go:34] DropPrefix done
I1224 09:59:06.347880       1 log.go:34] Resuming writes
I1224 09:59:06.347891       1 schema.go:79] Deleting schema for predicate: [Person]

[willem520]

Hi, I met the same problem about "writes are blocked". during the time about writes are blocked,if there are mutation to mudate,it means must be wait or return error to user?