MAINT: Revamping CLI printing and DSP logging

[jpbede]

@tlimoncelli before I continue my work, I would like to hear your feedback.

I'm currently working on making DNSControl concurrently (#1535). While testing, I have found that the pkg/printer is quite limited when used by DSPs. The printer pkg can't buffer the output per domain/DSP. Or maybe I'm just confused and don't know how to archive this.

Anyway, I'm currently revamping CLI printing and logging for DSPs/registrars.

My current idea is to use the context approach and make the DSP calls context aware. Each DSP/registrar call is given a *dnscontrol.Context. This context contains a logger that buffers the output for a domain. After the EndDomain call, this buffer is flushed to the CLI.

Additionally, the dnscontrol context contains a golang context, which can be use by some client packages. This solution may be useful later when we need to pass objects to the DSP/Registrar that are scoped to a domain. That would be a kinda big change, but would make us flexible for the future.

I've already tested this change with a quick and dirty concurrency PoC:

With concurrency:

$ hyperfine -i "dnscontrol preview"            
Benchmark 1: dnscontrol preview
  Time (mean ± σ):      2.041 s ±  0.547 s    [User: 0.579 s, System: 0.141 s]
  Range (min … max):    1.642 s …  3.408 s    10 runs```

Without concurrency:

$ hyperfine -i "dnscontrol preview" 
Benchmark 1: dnscontrol preview
  Time (mean ± σ):      6.638 s ±  1.901 s    [User: 0.467 s, System: 0.097 s]
  Range (min … max):    5.017 s … 11.147 s    10 runs

My repo contains 57 zones @ 1 DSP and a few registrars. There are no pending changes.

So what do you think about this? Don't mind the dirty code, it is a quick PoC :)

[tlimoncelli]

Wow! This is great! Thank you for working on this!

1. The person that created pkg/printer is no longer with the project. At the time of his departure, he was still experimenting with pkg/printer and what it should be. I don't think we ever decided. Therefore, feel free to rewrite or ignore it.

2. I noticed you use ctx.Log.Printf instead of printer.Printf (for example). While I realize that global variables are usually considered bad, but printer. has the benefit that it can be used anywhere. For example, a debug statement in a getter that doesn't have access to ctx. (Especially in situations where refactoring code to pass ctx all the way to helper functions doesn't seem right.) How do we have the benefit of both?

3. Here's a "stretch goal" for you. I usually run the output of preview/push through this filter. It removes any useless information:

#!/bin/bash

exec grep -v -e '^\.\.\.0 corrections$' \
   -e '^ *$' \
   -e '^0 corrections' \
   -e '\.\.\. \(skipping\)' \
   -e '^----- DNS Provider: ' \
   -e '^----- Registrar: ' \
   -e '^----- Getting nameservers from:'

Save the file as bin/filter-preview.sh and then run dnscontrol preview | bin/filter-preview.sh to see a much more useful output. As you can see, it removes "0 corrections" and other lines that aren't directly useful.

I'd rather have a "--brief" flag that knows to not output those statements (or --verbose that DOES output those lines?).

Is that something we could implement as part of this?

Thanks! Keep up the good work!

[jpbede]

2. I noticed you use ctx.Log.Printf instead of printer.Printf (for example). While I realize that global variables are usually considered bad, but printer. has the benefit that it can be used anywhere. For example, a debug statement in a getter that doesn't have access to ctx. (Especially in situations where refactoring code to pass ctx all the way to helper functions doesn't seem right.) How do we have the benefit of both?

Yes, this is something I was struggling with as well, but.... while writing the answer I got an idea. We could set a global variable per provider that contains the context. So the existing providers just need to implement a function, SetContext or something like that and change printer. to ctx.Log.. This way we have a global variable and don`t have to pass the ctx to helper functions.

New providers either use the ctx provided by the function call or do it the same way, with the SetContext function.

Here's a "stretch goal" for you. I usually run the output of preview/push through this filter. It removes any useless information: [....] I'd rather have a "--brief" flag that knows to not output those statements (or --verbose that DOES output those lines?). Is that something we could implement as part of this?

That is a great idea! I'll take a look at it and implement it when I revamping it.

[tlimoncelli]

Yes! Yes! These are great ideas!

[tlimoncelli]

Please rebase when you have a chance. The master branch has changed a lot recently.

[tlimoncelli]

Hey there!

I'm super excited that you're working on this. I think concurrency is going to be a huge improvement!

One thing we should discuss is how granular we want the concurrency to be.

My thought is that the lines numbered 2 and 3 would be concurrent:

1 $ dnscontrol preview
1 [INFO: PowerShell not available. Disabling Active Directory provider.]
2 ******************** Domain: sstatic.net
2 ----- Getting nameservers from: gcloud
2 ----- Getting nameservers from: r53
2 ----- DNS Provider: gcloud...
2 0 corrections
2 ----- DNS Provider: r53...
2 0 corrections
2 ----- Registrar: namedotcom_main...
2 0 corrections
3 ******************** Domain: blogoverflow.com
3 ----- Getting nameservers from: gcloud
3 ----- Getting nameservers from: r53
3 ----- DNS Provider: gcloud...
3 0 corrections
3 ----- DNS Provider: r53...
3 0 corrections
3 ----- Registrar: cscglobal_ltom215...
3 0 corrections
1 Done. 0 Corrections.

2 and 3 would run concurrently. Each would accumulate any printer (i.e. log) text in memory. When the domain is complete, the accumulated text would be output all at once (with some mechanism to make sure the printing doesn't get intermixed with other concurrent printing)

This would be a big benefit for sites with hundreds of domains. I know that at Stack Overflow "dnscontrol preview" takes a long time.

On the other hand, I'm concerned that the DNS providers might rate-limit us for doing GetZone() on hundreds of domains at the same time. Not all the provider code will back-off when they get rate limited.

1. Maybe some providers will have to be marked as "not concurrent" until they are updated to handle back-off properly?
2. There should be a command line flag to control how many goroutines are running at any time, including a value that means "run everything sequentially"

Thoughts?

[jpbede]

I'm super excited that you're working on this. I think concurrency is going to be a huge improvement!

You're welcome, unfortunately it took me a little longer to do things again.

My thought is that the lines numbered 2 and 3 would be concurrent: [....] 2 and 3 would run concurrently. Each would accumulate any printer (i.e. log) text in memory. When the domain is complete, the accumulated text would be output all at once (with some mechanism to make sure the printing doesn't get intermixed with other concurrent printing)

Yes, then we were both thinking the same thing 🙂. My current implementation runs each domain concurrently.

For printing there is BufferedPrinter which is passed within dnscontrol.Context to the provider pkg. It buffers the output and flushes to the console printer when EndDomain is called. To avoid mixing the output I'll use Mutex like I did it in buffered.go, so just one routine can flush at once.

1. Maybe some providers will have to be marked as "not concurrent" until they are updated to handle back-off properly?

I thought about the opposite option, flagging a provider as concurrent-safe. What do you think?

There should be a command line flag to control how many goroutines are running at any time, including a value that means > "run everything sequentially"

Good point. I have made a note of it and will then implement it.

[tlimoncelli]

(From my phone)

It’s safer to open into being concurrent. So, we should do the safe thing.

I wonder if we could write a test suite that providers would have to pass to show they’re safe.

Sent from Gmail Mobile

[tlimoncelli]

This morning I was thinking about whether we should have a --brief flag or a --verbose flag. I think the default should be brief output, with --verbose required to get the details.

Why did I change my mind? I just realized that 100% of the time that I've run "dnscontrol preview" in the last month I have always piped it to my filter script.

Previously I thought we should have a --brief flag out of a desire to not break backwards compatibility. However, nobody depends on the output (if they do, they can use --verbose). What's more important than protecting backwards compatibility is that all new users see the best output format, which is the brief format. Why? Because eventually "new users" will be the majority.