Error: Callback was already called.

[Andrew-Clement]

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]

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

• error: Error: No route to host (Could not found the next hop while running the traceroute)
• error: submission error {} (No error returned from the server)

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]

Thanks, sounds promising.

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