ndt5 v2 migration - data in tmp_ndt but not raw_ndt

[stephen-soltesz]

After adding v2 standard column support to ndt5 parser and ndt5 configuration to v2 gardener with changes to recognize ndt5, data is parsed into the tmp_ndt dataset tables but not copied to raw_ndt, though gardener does not seem to report errors.

Evidence of data in tmp tables

select date, COUNT(*) from `mlab-sandbox.tmp_ndt.ndt5` where date > date('2019-01-01') group by date order by date

The gardener logs include all steps, load, copy, delete, but they do not appear to take effect. The "deleted" tmp date partition is still present in the query above. The "load" and "dedup" steps appear to take 20-30sec, but the "copy" step is only 100ms, suggesting that it is not actually being performed. (these values are representative of other dates).

Why is data not reaching the raw_ndt.ndt5 table?

Logs from gardener for a recent date:

2021/12/21 13:21:00 job.go:148: ndt/ndt5/2020/05/23/
2021/12/21 13:21:00 job-service.go:218: Dispatching 20200523:ndt/ndt5
2021/12/21 13:21:01 tracker.go:192: 20200523:ndt/ndt5 {init 2021-12-21 13:21:00.966864856 +0000 UTC m=+43124.080562051 2021-12-21 13:21:00.966864856 +0000 UTC m=+43124.080562051 } -> parsing
2021/12/21 13:22:08 tracker.go:192: 20200523:ndt/ndt5 {parsing 2021-12-21 13:21:01.019313161 +0000 UTC m=+43124.133010309 2021-12-21 13:22:08.261470045 +0000 UTC m=+43191.375167220 ndt/ndt5/2020/05/23/20200525T105125.608565Z-ndt5-mlab1-dfw07-ndt.tgz} -> postProcessing
2021/12/21 13:22:12 tracker.go:192: 20200523:ndt/ndt5 {postProcessing 2021-12-21 13:22:08.262111218 +0000 UTC m=+43191.375808366 2021-12-21 13:22:08.262111218 +0000 UTC m=+43191.375808366 } -> loading
2021/12/21 13:22:54 actions.go:310: 20200523:ndt/ndt5 Load took 21s (after 0s waiting), 5660539 rows with 4023713475 bytes, from 10031 files with 7618555066 bytes
2021/12/21 13:22:54 tracker.go:192: 20200523:ndt/ndt5 {loading 2021-12-21 13:22:12.067257088 +0000 UTC m=+43195.180954290 2021-12-21 13:22:12.067257088 +0000 UTC m=+43195.180954290 } -> deduplicating
2021/12/21 13:23:32 actions.go:163: 20200523:ndt/ndt5 Dedup took 33.6s (after 0s waiting),  4.95 Slot Minutes, 1 Rows affected, 438807 MB Processed, 438807 MB Billed
2021/12/21 13:23:32 actions.go:164: 20200523:ndt/ndt5 Dedup: &{BIEngineStatistics:<nil> BillingTier:1 CacheHit:false StatementType:DELETE TotalBytesBilled:438807035904 TotalBytesProcessed:438807012104 TotalBytesProcessedAccuracy: QueryPlan:[0xc0003f6780 0xc0003f68c0 0xc0003f6c80 0xc0003f6dc0 0xc0003f6f00 0xc0003f7040] NumDMLAffectedRows:1 DMLStats:0xc000d5b600 Timeline:[0xc0009fc030 0xc0009fc060 0xc0009fc090 0xc0009fc0f0 0xc0009fc120 0xc0009fc150 0xc0009fc180 0xc0009fc1b0 0xc0009fc1e0 0xc0009fc210 0xc0009fc240 0xc0009fc270 0xc0009fc2a0 0xc0009fc2d0 0xc0009fc300 0xc0009fc330 0xc0009fc360] ReferencedTables:[0xc000aee580] Schema:[] SlotMillis:296773 UndeclaredQueryParameterNames:[] DDLTargetTable:<nil> DDLOperationPerformed: DDLTargetRoutine:<nil>}
2021/12/21 13:23:32 tracker.go:192: 20200523:ndt/ndt5 {deduplicating 2021-12-21 13:22:54.285098236 +0000 UTC m=+43237.398795384 2021-12-21 13:22:54.285098236 +0000 UTC m=+43237.398795384 } -> copying
2021/12/21 13:23:37 actions.go:347: 20200523:ndt/ndt5 Copy took 100ms (after 0s waiting), 0 MB Processed
2021/12/21 13:23:37 tracker.go:192: 20200523:ndt/ndt5 {copying 2021-12-21 13:23:32.88794288 +0000 UTC m=+43276.001640046 2021-12-21 13:23:32.88794288 +0000 UTC m=+43276.001640046 } -> deleting
2021/12/21 13:23:42 ops.go:212: Deleting mlab-sandbox:tmp_ndt.ndt5$20200523
2021/12/21 13:23:44 tracker.go:192: 20200523:ndt/ndt5 {deleting 2021-12-21 13:23:37.683873442 +0000 UTC m=+43280.797570590 2021-12-21 13:23:37.683873442 +0000 UTC m=+43280.797570590 } -> joining
2021/12/21 13:23:47 tracker.go:192: 20200523:ndt/ndt5 {joining 2021-12-21 13:23:44.727312732 +0000 UTC m=+43287.841009886 2021-12-21 13:23:44.727312732 +0000 UTC m=+43287.841009886 } -> complete