search

ixmaps / IXmapsClient

Client for IXmaps traceroute submission
GNU Affero General Public License v3.0
9 stars 5 forks source link

Error: Callback was already called. #84

Open Andrew-Clement opened 8 years ago

Andrew-Clement commented 8 years ago

I was running the full TRset (starting around 3PM EDT Nov 5) and got over halfway when the Client stopped on "dest": "ecuad.ca": 

    **Error: Callback was already called.**

Here is the Terminal log starting with the last complete TR submission: (UBC.ca)

STATUS: Host ubc.ca info: now running ubc.ca from 00: all trsets info: options{ "submitter": "AndrewC", "postal_code": "V8K 2W9", "dest": "ubc.ca", "trset": "00: all trsets", "queries": 4, "timeout": 750, "maxhops": 24, "raw_protocol": "ICMP", "max_sequential_errors": 4, "include_platform_traceroute": false, "platform_protocol": "Default", "platform_limit_ms": 60000, "city": "Sidney", "isp": "Shaw Communications Inc." } hop: {"pass":1,"hop":1,"ttl":1,"ip":"192.168.0.1","rtt":"1.54"} hop: {"pass":1,"hop":2,"ttl":2,"ip":"0.0.0.0","rtt":"8.55"} hop: {"pass":1,"hop":3,"ttl":3,"ip":"64.59.162.185","rtt":"10.58"} hop: {"pass":1,"hop":4,"ttl":4,"ip":"66.163.72.9","rtt":"16.26"} hop: {"pass":1,"hop":5,"ttl":5,"ip":"66.163.68.129","rtt":"14.31"} hop: {"pass":1,"hop":6,"ttl":6,"ip":"66.163.68.222","rtt":"16.75"} hop: {"pass":1,"hop":7,"ttl":7,"ip":"64.251.87.210","rtt":"13.77"} hop: {"pass":1,"hop":8,"ttl":8,"ip":"207.23.253.33","rtt":"12.31"} hop: {"pass":1,"hop":9,"ttl":9,"ip":"207.23.240.85","rtt":"14.49"} hop: {"pass":1,"hop":10,"ttl":10,"ip":"137.82.123.138","rtt":"17.95"} hop: {"pass":1,"hop":11,"ttl":11,"ip":"137.82.123.113","rtt":"15.24"} hop: {"pass":1,"hop":12,"ttl":12,"ip":"142.103.246.21","rtt":"15.17"} hop: {"pass":1,"hop":13,"ttl":13,"ip":"142.103.59.217","rtt":"14.08"} complete pass 1 pass: 0 hop: {"pass":2,"hop":1,"ttl":1,"ip":"192.168.0.1","rtt":"1.65"} hop: {"pass":2,"hop":2,"ttl":2,"ip":"0.0.0.0","rtt":"8.13"} hop: {"pass":2,"hop":3,"ttl":3,"ip":"64.59.162.185","rtt":"11.05"} hop: {"pass":2,"hop":4,"ttl":4,"ip":"66.163.72.9","rtt":"14.94"} hop: {"pass":2,"hop":5,"ttl":5,"ip":"66.163.68.129","rtt":"12.78"} hop: {"pass":2,"hop":6,"ttl":6,"ip":"66.163.68.222","rtt":"13.66"} hop: {"pass":2,"hop":7,"ttl":7,"ip":"64.251.87.210","rtt":"13.35"} hop: {"pass":2,"hop":8,"ttl":8,"ip":"207.23.253.33","rtt":"13.57"} hop: {"pass":2,"hop":9,"ttl":9,"ip":"207.23.240.85","rtt":"14.04"} hop: {"pass":2,"hop":10,"ttl":10,"ip":"137.82.123.138","rtt":"14.24"} hop: {"pass":2,"hop":11,"ttl":11,"ip":"137.82.123.113","rtt":"14.42"} hop: {"pass":2,"hop":12,"ttl":12,"ip":"142.103.246.21","rtt":"13.97"} hop: {"pass":2,"hop":13,"ttl":13,"ip":"142.103.59.217","rtt":"14.09"} complete pass 2 pass: 1 hop: {"pass":3,"hop":1,"ttl":1,"ip":"192.168.0.1","rtt":"1.72"} hop: {"pass":3,"hop":2,"ttl":2,"ip":"0.0.0.0","rtt":"9.35"} hop: {"pass":3,"hop":3,"ttl":3,"ip":"64.59.162.185","rtt":"9.00"} hop: {"pass":3,"hop":4,"ttl":4,"ip":"66.163.72.9","rtt":"12.31"} hop: {"pass":3,"hop":5,"ttl":5,"ip":"66.163.68.129","rtt":"18.17"} hop: {"pass":3,"hop":6,"ttl":6,"ip":"66.163.68.222","rtt":"13.40"} hop: {"pass":3,"hop":7,"ttl":7,"ip":"64.251.87.210","rtt":"15.17"} hop: {"pass":3,"hop":8,"ttl":8,"ip":"207.23.253.33","rtt":"15.46"} hop: {"pass":3,"hop":9,"ttl":9,"ip":"207.23.240.85","rtt":"14.88"} hop: {"pass":3,"hop":10,"ttl":10,"ip":"137.82.123.138","rtt":"15.13"} hop: {"pass":3,"hop":11,"ttl":11,"ip":"137.82.123.113","rtt":"20.08"} hop: {"pass":3,"hop":12,"ttl":12,"ip":"142.103.246.21","rtt":"17.72"} hop: {"pass":3,"hop":13,"ttl":13,"ip":"142.103.59.217","rtt":"18.79"} complete pass 3 pass: 2 hop: {"pass":4,"hop":1,"ttl":1,"ip":"192.168.0.1","rtt":"1.20"} hop: {"pass":4,"hop":2,"ttl":2,"ip":"0.0.0.0","rtt":"8.63"} hop: {"pass":4,"hop":3,"ttl":3,"ip":"64.59.162.185","rtt":"12.22"} hop: {"pass":4,"hop":4,"ttl":4,"ip":"66.163.72.9","rtt":"12.16"} hop: {"pass":4,"hop":5,"ttl":5,"ip":"66.163.68.129","rtt":"12.91"} hop: {"pass":4,"hop":6,"ttl":6,"ip":"66.163.68.222","rtt":"13.06"} hop: {"pass":4,"hop":7,"ttl":7,"ip":"64.251.87.210","rtt":"13.68"} hop: {"pass":4,"hop":8,"ttl":8,"ip":"207.23.253.33","rtt":"13.15"} hop: {"pass":4,"hop":9,"ttl":9,"ip":"207.23.240.85","rtt":"13.79"} hop: {"pass":4,"hop":10,"ttl":10,"ip":"137.82.123.138","rtt":"13.99"} hop: {"pass":4,"hop":11,"ttl":11,"ip":"137.82.123.113","rtt":"13.44"} hop: {"pass":4,"hop":12,"ttl":12,"ip":"142.103.246.21","rtt":"15.53"} hop: {"pass":4,"hop":13,"ttl":13,"ip":"142.103.59.217","rtt":"14.25"} complete pass 4 pass: 3 done: 4 queries SUBMITTRACE post { "timeout": 750, "queries": 4, "dest": "ubc.ca", "dest_ip": "142.103.59.217", "submitter": "AndrewC", "city": "Sidney", "postal_code": "V8K 2W9", "maxhops": 24, "os": "Darwin", "traceroute_submissions": [ { "client": "IXmapsClient 1.0.6", "protocol": "ICMP", "tr_data": [ [ { "pass": 1, "hop": 1, "ttl": 1, "ip": "192.168.0.1", "rtt": "1.54" }, { "pass": 1, "hop": 2, "ttl": 2, "ip": "0.0.0.0", "rtt": "8.55" }, { "pass": 1, "hop": 3, "ttl": 3, "ip": "64.59.162.185", "rtt": "10.58" }, { "pass": 1, "hop": 4, "ttl": 4, "ip": "66.163.72.9", "rtt": "16.26" }, { "pass": 1, "hop": 5, "ttl": 5, "ip": "66.163.68.129", "rtt": "14.31" }, { "pass": 1, "hop": 6, "ttl": 6, "ip": "66.163.68.222", "rtt": "16.75" }, { "pass": 1, "hop": 7, "ttl": 7, "ip": "64.251.87.210", "rtt": "13.77" }, { "pass": 1, "hop": 8, "ttl": 8, "ip": "207.23.253.33", "rtt": "12.31" }, { "pass": 1, "hop": 9, "ttl": 9, "ip": "207.23.240.85", "rtt": "14.49" }, { "pass": 1, "hop": 10, "ttl": 10, "ip": "137.82.123.138", "rtt": "17.95" }, { "pass": 1, "hop": 11, "ttl": 11, "ip": "137.82.123.113", "rtt": "15.24" }, { "pass": 1, "hop": 12, "ttl": 12, "ip": "142.103.246.21", "rtt": "15.17" }, { "pass": 1, "hop": 13, "ttl": 13, "ip": "142.103.59.217", "rtt": "14.08" } ], [ { "pass": 2, "hop": 1, "ttl": 1, "ip": "192.168.0.1", "rtt": "1.65" }, { "pass": 2, "hop": 2, "ttl": 2, "ip": "0.0.0.0", "rtt": "8.13" }, { "pass": 2, "hop": 3, "ttl": 3, "ip": "64.59.162.185", "rtt": "11.05" }, { "pass": 2, "hop": 4, "ttl": 4, "ip": "66.163.72.9", "rtt": "14.94" }, { "pass": 2, "hop": 5, "ttl": 5, "ip": "66.163.68.129", "rtt": "12.78" }, { "pass": 2, "hop": 6, "ttl": 6, "ip": "66.163.68.222", "rtt": "13.66" }, { "pass": 2, "hop": 7, "ttl": 7, "ip": "64.251.87.210", "rtt": "13.35" }, { "pass": 2, "hop": 8, "ttl": 8, "ip": "207.23.253.33", "rtt": "13.57" }, { "pass": 2, "hop": 9, "ttl": 9, "ip": "207.23.240.85", "rtt": "14.04" }, { "pass": 2, "hop": 10, "ttl": 10, "ip": "137.82.123.138", "rtt": "14.24" }, { "pass": 2, "hop": 11, "ttl": 11, "ip": "137.82.123.113", "rtt": "14.42" }, { "pass": 2, "hop": 12, "ttl": 12, "ip": "142.103.246.21", "rtt": "13.97" }, { "pass": 2, "hop": 13, "ttl": 13, "ip": "142.103.59.217", "rtt": "14.09" } ], [ { "pass": 3, "hop": 1, "ttl": 1, "ip": "192.168.0.1", "rtt": "1.72" }, { "pass": 3, "hop": 2, "ttl": 2, "ip": "0.0.0.0", "rtt": "9.35" }, { "pass": 3, "hop": 3, "ttl": 3, "ip": "64.59.162.185", "rtt": "9.00" }, { "pass": 3, "hop": 4, "ttl": 4, "ip": "66.163.72.9", "rtt": "12.31" }, { "pass": 3, "hop": 5, "ttl": 5, "ip": "66.163.68.129", "rtt": "18.17" }, { "pass": 3, "hop": 6, "ttl": 6, "ip": "66.163.68.222", "rtt": "13.40" }, { "pass": 3, "hop": 7, "ttl": 7, "ip": "64.251.87.210", "rtt": "15.17" }, { "pass": 3, "hop": 8, "ttl": 8, "ip": "207.23.253.33", "rtt": "15.46" }, { "pass": 3, "hop": 9, "ttl": 9, "ip": "207.23.240.85", "rtt": "14.88" }, { "pass": 3, "hop": 10, "ttl": 10, "ip": "137.82.123.138", "rtt": "15.13" }, { "pass": 3, "hop": 11, "ttl": 11, "ip": "137.82.123.113", "rtt": "20.08" }, { "pass": 3, "hop": 12, "ttl": 12, "ip": "142.103.246.21", "rtt": "17.72" }, { "pass": 3, "hop": 13, "ttl": 13, "ip": "142.103.59.217", "rtt": "18.79" } ], [ { "pass": 4, "hop": 1, "ttl": 1, "ip": "192.168.0.1", "rtt": "1.20" }, { "pass": 4, "hop": 2, "ttl": 2, "ip": "0.0.0.0", "rtt": "8.63" }, { "pass": 4, "hop": 3, "ttl": 3, "ip": "64.59.162.185", "rtt": "12.22" }, { "pass": 4, "hop": 4, "ttl": 4, "ip": "66.163.72.9", "rtt": "12.16" }, { "pass": 4, "hop": 5, "ttl": 5, "ip": "66.163.68.129", "rtt": "12.91" }, { "pass": 4, "hop": 6, "ttl": 6, "ip": "66.163.68.222", "rtt": "13.06" }, { "pass": 4, "hop": 7, "ttl": 7, "ip": "64.251.87.210", "rtt": "13.68" }, { "pass": 4, "hop": 8, "ttl": 8, "ip": "207.23.253.33", "rtt": "13.15" }, { "pass": 4, "hop": 9, "ttl": 9, "ip": "207.23.240.85", "rtt": "13.79" }, { "pass": 4, "hop": 10, "ttl": 10, "ip": "137.82.123.138", "rtt": "13.99" }, { "pass": 4, "hop": 11, "ttl": 11, "ip": "137.82.123.113", "rtt": "13.44" }, { "pass": 4, "hop": 12, "ttl": 12, "ip": "142.103.246.21", "rtt": "15.53" }, { "pass": 4, "hop": 13, "ttl": 13, "ip": "142.103.59.217", "rtt": "14.25" } ] ], "result": "completed" } ] }submitted: Processed ubc.ca (142.103.59.217) - TRID 320202 STATUS: Host ecuad.ca info: now running ecuad.ca from 00: all trsets info: options{ "submitter": "AndrewC", "postal_code": "V8K 2W9", "dest": "ecuad.ca", "trset": "00: all trsets", "queries": 4, "timeout": 750, "maxhops": 24, "raw_protocol": "ICMP", "max_sequential_errors": 4, "include_platform_traceroute": false, "platform_protocol": "Default", "platform_limit_ms": 60000, "city": "Sidney", "isp": "Shaw Communications Inc." } hop: {"pass":1,"hop":1,"ttl":1,"rtt":-1,"err":"timeout"} hop: {"pass":1,"hop":2,"ttl":2,"rtt":-1,"err":"timeout"} hop: {"pass":1,"hop":3,"ttl":3,"rtt":-1,"err":"timeout"} hop: {"pass":1,"hop":4,"ttl":4,"rtt":-1,"err":"timeout"} maxhops 24 pass: 0 hop: {"pass":2,"hop":1,"ttl":1,"rtt":-1,"err":"timeout"} maxhops 24 pass: 1 hop: {"pass":3,"hop":1,"ttl":1,"rtt":-1,"err":"timeout"} maxhops 24 pass: 2 error: Error: No route to host SUBMITTRACE post { "timeout": 750, "queries": 4, "dest": "ecuad.ca", "dest_ip": "192.168.0.6", "submitter": "AndrewC", "city": "Sidney", "postal_code": "V8K 2W9", "maxhops": 24, "os": "Darwin", "traceroute_submissions": [ null ], "error": "{}" } error: submission error {} hop: {"pass":4,"hop":1,"ttl":1,"rtt":-1,"err":"timeout"} maxhops 24 pass: 3 done: 4 queries /Applications/IXmapsClient.app/Contents/Resources/ixmaps-darwin/node_modules/async/lib/async.js:43 if (fn === null) throw new Error("Callback was already called."); ^

Error: Callback was already called. at /Applications/IXmapsClient.app/Contents/Resources/ixmaps-darwin/node_modules/async/lib/async.js:43:36 at /Applications/IXmapsClient.app/Contents/Resources/ixmaps-darwin/node_modules/async/lib/async.js:718:17 at /Applications/IXmapsClient.app/Contents/Resources/ixmaps-darwin/node_modules/async/lib/async.js:167:37 at Object.rawProcessor.done (/Applications/IXmapsClient.app/Contents/Resources/ixmaps-darwin/lib/socket-trace.js:33:7) at doPasses (/Applications/IXmapsClient.app/Contents/Resources/ixmaps-darwin/lib/socket-trace.js:43:20) at end (/Applications/IXmapsClient.app/Contents/Resources/ixmaps-darwin/lib/socket-trace.js:119:9) at null._onTimeout (/Applications/IXmapsClient.app/Contents/Resources/ixmaps-darwin/lib/socket-trace.js:64:7) at Timer.listOnTimeout (timers.js:92:15) Macintosh-272:ixmaps-darwin andrewclementAir$

agamba commented 7 years ago

This error seems to me to be caused by a momentary lost of internet connection on the Client's side. See the lines:

Then the following errors seem to propagate from these.

The way we can attempt to replicate this deliberately turning off the internet connection when the traceroute is running and observe the errors. Further refinements would include adding a more graceful error message and preventing the IXmapsClient from crashing.

Andrew-Clement commented 7 years ago

Thanks, sounds promising.

Have you tried this ("deliberately turning off the internet connection when the traceroute is running")?