IPs returning multiple ASNs cuts off legitimate responses #11

dacamp · 2018-10-08T20:21:59Z

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>

The text was updated successfully, but these errors were encountered:

dacamp · 2018-10-08T20:28:26Z

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 · 2018-10-08T20:30:22Z

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

ammario · 2018-10-08T20:36:12Z

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 · 2018-10-08T20:51:51Z

That change looks fine though 👍

dacamp · 2018-10-08T21:49:57Z

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 · 2018-10-08T21:50:41Z

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 · 2018-10-08T21:52:40Z

That change looks fine though 👍

Working on a diff

dacamp · 2018-10-08T21:55:45Z

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 · 2018-10-08T22:08:47Z

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 · 2018-10-08T22:41:36Z

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 · 2018-10-09T01:14:24Z

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 · 2018-10-09T01:17:09Z

I actually tested B:

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

ammario · 2018-10-09T14:42:04Z

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

dacamp · 2018-10-09T17:34:30Z

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 · 2018-10-09T17:39:49Z

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

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

IPs returning multiple ASNs cuts off legitimate responses #11

IPs returning multiple ASNs cuts off legitimate responses #11

dacamp commented Oct 8, 2018

dacamp commented Oct 8, 2018

ammario commented Oct 8, 2018 •

edited

Loading

ammario commented Oct 8, 2018

ammario commented Oct 8, 2018

dacamp commented Oct 8, 2018

dacamp commented Oct 8, 2018

dacamp commented Oct 8, 2018

dacamp commented Oct 8, 2018

ammario commented Oct 8, 2018 •

edited

Loading

dacamp commented Oct 8, 2018 •

edited

Loading

dacamp commented Oct 9, 2018 •

edited

Loading

dacamp commented Oct 9, 2018

ammario commented Oct 9, 2018

dacamp commented Oct 9, 2018

dacamp commented Oct 9, 2018

IPs returning multiple ASNs cuts off legitimate responses #11

IPs returning multiple ASNs cuts off legitimate responses #11

Comments

dacamp commented Oct 8, 2018

dacamp commented Oct 8, 2018

ammario commented Oct 8, 2018 • edited Loading

ammario commented Oct 8, 2018

ammario commented Oct 8, 2018

dacamp commented Oct 8, 2018

dacamp commented Oct 8, 2018

dacamp commented Oct 8, 2018

dacamp commented Oct 8, 2018

ammario commented Oct 8, 2018 • edited Loading

dacamp commented Oct 8, 2018 • edited Loading

dacamp commented Oct 9, 2018 • edited Loading

dacamp commented Oct 9, 2018

ammario commented Oct 9, 2018

dacamp commented Oct 9, 2018

dacamp commented Oct 9, 2018

ammario commented Oct 8, 2018 •

edited

Loading

ammario commented Oct 8, 2018 •

edited

Loading

dacamp commented Oct 8, 2018 •

edited

Loading

dacamp commented Oct 9, 2018 •

edited

Loading