IPs returning multiple ASNs cuts off legitimate responses

dacamp commented 5 years ago

When using the whoisClient and the LookupIPs function there are times when Cymru returns multiple ASNs (I haven't looked into why).

Because of the finished boolean checking the length of the response vs the capacity of the response some legitimate IPs are getting dropped from the response:

if len(resp) == cap(resp) {
        finished = true
}

I added in some debugging

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: 2500
========================================================

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? true
isisp: whoisClient.LookupIPs: Scanner Unprocessed Value: <AS> | <IP>  | <BGP Prefix> | <CC> | <Registry> | <Allocated>  | <AS Name> # Edited
isisp: whoisClient.LookupIPs: Scanner Open? true
isisp: whoisClient.LookupIPs: Scanner Unprocessed Value: <AS> | <IP>  | <BGP Prefix> | <CC> | <Registry> | <Allocated>  | <AS Name> # Edited
isisp: whoisClient.LookupIPs: Scanner Open? true
isisp: whoisClient.LookupIPs: Scanner Unprocessed Value: <AS> | <IP>  | <BGP Prefix> | <CC> | <Registry> | <Allocated>  | <AS Name> # Edited
isisp: whoisClient.LookupIPs: Scanner Open? true
isisp: whoisClient.LookupIPs: Scanner Unprocessed Value: <AS> | <IP>  | <BGP Prefix> | <CC> | <Registry> | <Allocated>  | <AS Name> # Edited
isisp: whoisClient.LookupIPs: Scanner Open? true
isisp: whoisClient.LookupIPs: Scanner Unprocessed Value: <AS> | <IP>  | <BGP Prefix> | <CC> | <Registry> | <Allocated>  | <AS Name> # Edited
isisp: whoisClient.LookupIPs: Scanner Open? true
isisp: whoisClient.LookupIPs: Scanner Unprocessed Value: <AS> | <IP>  | <BGP Prefix> | <CC> | <Registry> | <Allocated>  | <AS Name> # Edited
isisp: whoisClient.LookupIPs: Scanner Open? false
isisp: whoisClient.LookupIPs: Scan missed results count: 6
isisp: whoisClient.LookupIPs: Scanner Error: <nil>

dacamp commented 5 years ago

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 commented 5 years ago

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

ammario commented 5 years ago

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 commented 5 years ago

That change looks fine though :+1:

dacamp commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

That change looks fine though 👍

Working on a diff

dacamp commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

I actually tested B:

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

ammario commented 5 years ago

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

dacamp commented 5 years ago

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 commented 5 years ago

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

ammario / ipisp

IPs returning multiple ASNs cuts off legitimate responses #11