IPs returning multiple ASNs cuts off legitimate responses

[ammario]

IPs returning multiple ASNs cuts off legitimate responses

[dacamp]

How do you feel about something like this

-       var finished bool

        // Read results
-       for !finished && c.sc.Scan() {
-
+       for {
+               if ok := c.sc.Scan(); !ok {
+                       break
+               }
@@ -154,10 +172,37 @@ func (c *whoisClient) LookupIPs(ips []net.IP) (resp []Response, err error) {

                // Add to response slice
                resp = append(resp, re)
-               if len(resp) == cap(resp) {
-                       finished = true
-               }

With my above debug output:

Raw Value:  <AS> | <IP>  | <BGP Prefix> | <CC> | <Registry> | <Allocated>  | <AS Name> # Edited
isisp: whoisClient.LookupIPs: bad ASN count: 2 # related to issue 10
isisp: whoisClient.LookupIPs: Scan count: 2506
========================================================

isisp: whoisClient.LookupIPs: ATTENTION: saw <IP> 2 number of times # Edited
isisp: whoisClient.LookupIPs: ATTENTION: saw <IP> 2 number of times # Edited
isisp: whoisClient.LookupIPs: ATTENTION: saw <IP> 2 number of times # Edited
isisp: whoisClient.LookupIPs: ATTENTION: saw <IP> 2 number of times # Edited
isisp: whoisClient.LookupIPs: ATTENTION: saw <IP> 2 number of times # Edited
isisp: whoisClient.LookupIPs: ATTENTION: saw <IP> 2 number of times # Edited
isisp: whoisClient.LookupIPs: ATTENTION: saw <IP> 2 number of times # Edited
isisp: whoisClient.LookupIPs: ATTENTION: saw <IP> 2 number of times # Edited
========================================================

isisp: whoisClient.LookupIPs: Scanner Open? false
isisp: whoisClient.LookupIPs: Scan missed results count: 0
isisp: whoisClient.LookupIPs: Scanner Error: <nil>

The only thing I noticed was that there's a delay from the break to the return of resp and err from within *whoisClient.LookupIPs, which I'm guessing is probably the underlying net.Conn waiting for either a timeout or the deadline to expire. It seems to be a blocking request, so the client is unable to close the connection. That's a different bug and I can file a new issue for that if you think it's important.

Thanks!

[ammario]

Could you give me an example of an IP that break?

[ammario]

Where exactly are you seeing the delay? The only thing I could think of that could cause that is a deferred statement, but the only thing deferred is a mutex unlock.

If there is actually a real problem, please open a new issue.

[ammario]

That change looks fine though 👍

[dacamp]

103.57.80.88 is a good example. Even if you use the web client http://whois.cymru.com/ it'll return both ASNs.

[dacamp]

Where exactly are you seeing the delay? The only thing I could think of that could cause that is a deferred statement, but the only thing deferred is a mutex unlock.

If there is actually a real problem, please open a new issue.

Yeah I'll need to investigate a lot more before I'm there, but I'm looking into it. I'll open a new issue when I find it. Thanks!

[dacamp]

That change looks fine though 👍

Working on a diff

[dacamp]

This was the timeout I'm talking about. I'd guess the net.Conn read socket isn't closed yet (5 second deadline and 10 second timeout). This change probably requires a little refactoring and I may be an edge case because I'm doing thousands of IPs per request.

➜  ipisp git:(multiASNs) ✗ go test
--- FAIL: TestWhoisClient (6.21s)
    --- FAIL: TestWhoisClient/IP (6.00s)
        --- FAIL: TestWhoisClient/IP/Raw_IP (0.00s)
            require.go:794:
                	Error Trace:	client_test.go:45
                	Error:      	Received unexpected error:
                	            	write tcp 172.24.70.10:59689->38.229.36.132:43: i/o timeout
                	Test:       	TestWhoisClient/IP/Raw_IP
        --- FAIL: TestWhoisClient/IP/Multiple_ASNs (0.00s)
            require.go:794:
                	Error Trace:	client_test.go:60
                	Error:      	Received unexpected error:
                	            	write tcp 172.24.70.10:59689->38.229.36.132:43: i/o timeout
                	Test:       	TestWhoisClient/IP/Multiple_ASNs
FAIL
exit status 1
FAIL	github.com/ammario/ipisp	6.226s

[ammario]

If this is occuring on LookupIPs, I think you must be experiencing some sort of rate limit. We set the WriteDeadline dynamically based on the number of requested IPs.

[dacamp]

The timeout example I sent was from go test against a single IP. I think Scan may be a blocking call until a deadline or a timeout happens, which wouldn't happen when you look for the right amount of response requests like you currently have. Hmmm, guess a better solution is still needed.

[dacamp]

So I modified the code above to include some debug timing information:

+       for {
+               fmt.Println("isp: whoisClient.LookupIPs: entering for loop, waiting to scan")
+               start := time.Now()
+               if ok := c.sc.Scan(); !ok {
+                       fmt.Printf("isp: whoisClient.LookupIPs: scanner is closed taking %s\n", time.Since(start))
+                       break
+               }
+               fmt.Println("isp: whoisClient.LookupIPs: scanner is open")

Here's the output of the above

isp: whoisClient.LookupIPs: entering for loop, waiting to scan # if ok := c.sc.Scan(); !ok
isp: whoisClient.LookupIPs: scanner is closed taking 29.895171542s 

What's happening is that c.sc.Scan() is blocking because the Cymru server is expecting the end signal. The server is configured with a 30 second timeout, which I confirmed by using netcat and a stopwatch. Those additional 3 seconds are me typing in 'begin', 'verbose', and the IP.

➜  example time nc whois.cymru.com 43
begin
Bulk mode; whois.cymru.com [2018-10-09 01:03:58 +0000]
verbose
178.91.119.166
9198    | 178.91.119.166   | 178.91.116.0/22     | KZ | ripencc  | 2009-11-26 | KAZTELECOM-AS, KZ
nc whois.cymru.com 43  0.00s user 0.00s system 0% cpu 32.957 total

I can think of a couple ways to handle this, but they aren't great. Suggestions would be appreciated.

• A. Create a counter := make(map[string]int) to ensure we've seen each IP in the ips parameter at least once and apply logic to set the finished boolean to true. This is probably the easiest.
• B. Set a c.Conn.SetReadDeadline() timeout to 5 seconds per Scan(). Probably the most expensive, but would limit the timeout per Scan i.e.

for {
   c.Conn.SetReadDeadline(time.Now().Add(time.Second *5))
   if ok := c.sc.Scan(); !ok {
      break
   }

• C. A major refactor using either channels or the underlying net.Conn. Neither feel like a good solution and probably wouldn't be backwards compatible.

[dacamp]

I actually tested B:

isp: whoisClient.LookupIPs: entering for loop, waiting to scan
isp: whoisClient.LookupIPs: scanner is closed taking 5.000203191s

[ammario]

I like the counter idea, but I think it would just have to be a set (map[string]struct{})

[dacamp]

Ahh right, the empty struct makes more sense. I was still using my debug map when I was trying to figure out what was going on :)

[dacamp]

I just tested RFC 1918 IPs and 0.0.0.0. Cymru returns the IP in the response, so the map should work!

Raw Value: NA      | 127.0.0.1        | NA                  |    | other    |            | NA
Raw Value: NA      | 192.168.192.168  | NA                  |    | other    |            | NA
Raw Value: NA      | 0.0.0.0          | NA                  |    | other    |            | NA