Tor-resolve resolve dns only once per minute for github.com

Question

I'm trying to clone project from github via Tor.

# torsocks git clone http://github/project/project.git
: Could not resolve host: github.com

I'm going to catch a failure of resolving of IP.

Next, I'm trying to find a problem, simply by checking the Tor-resolve binary:

Wed Nov 13 20:32:37 NOVT 2013
Nov 13 20:32:37.884 [debug] main(): defaulting to localhost
Nov 13 20:32:37.884 [debug] main(): defaulting to port 9050
Nov 13 20:32:37.885 [warn] Got SOCKS5 status response '4': host is unreachable
Wed Nov 13 20:32:38 NOVT 2013
Nov 13 20:32:38.888 [debug] main(): defaulting to localhost
Nov 13 20:32:38.888 [debug] main(): defaulting to port 9050
Nov 13 20:32:38.888 [warn] Got SOCKS5 status response '4': host is unreachable
Wed Nov 13 20:32:39 NOVT 2013
Nov 13 20:32:39.890 [debug] main(): defaulting to localhost
Nov 13 20:32:39.890 [debug] main(): defaulting to port 9050
Nov 13 20:32:39.890 [warn] Got SOCKS5 status response '4': host is unreachable
Wed Nov 13 20:32:40 NOVT 2013
Nov 13 20:32:40.893 [debug] main(): defaulting to localhost
Nov 13 20:32:40.893 [debug] main(): defaulting to port 9050
192.30.252.129
Wed Nov 13 20:32:42 NOVT 2013
Nov 13 20:32:42.062 [debug] main(): defaulting to localhost
Nov 13 20:32:42.062 [debug] main(): defaulting to port 9050
Nov 13 20:32:42.063 [warn] Got SOCKS5 status response '4': host is unreachable
Wed Nov 13 20:32:43 NOVT 2013
Nov 13 20:32:43.065 [debug] main(): defaulting to localhost
Nov 13 20:32:43.065 [debug] main(): defaulting to port 9050
Nov 13 20:32:43.065 [warn] Got SOCKS5 status response '4': host is unreachable
Wed Nov 13 20:32:44 NOVT 2013
Nov 13 20:32:44.081 [debug] main(): defaulting to localhost
Nov 13 20:32:44.081 [debug] main(): defaulting to port 9050
Nov 13 20:32:44.084 [warn] Got SOCKS5 status response '4': host is unreachable

I have found that, I'm getting lucky only once, per minute:

fails
....
Wed Nov 13 20:33:42 NOVT 2013
Nov 13 20:33:42.285 [debug] main(): defaulting to localhost
Nov 13 20:33:42.285 [debug] main(): defaulting to port 9050
192.30.252.129
....
fails
....
Wed Nov 13 20:34:44 NOVT 2013
Nov 13 20:34:44.711 [debug] main(): defaulting to localhost
Nov 13 20:34:44.711 [debug] main(): defaulting to port 9050
192.30.252.128
....
fails

All is ok with any other domain, I can resolve google dns many times at line:

$ tor-resolve -v google.com
Nov 14 03:49:20.391 [debug] main(): defaulting to localhost
Nov 14 03:49:20.391 [debug] main(): defaulting to port 9050
173.194.37.69
$ tor-resolve -v google.com
Nov 14 03:49:20.623 [debug] main(): defaulting to localhost
Nov 14 03:49:20.623 [debug] main(): defaulting to port 9050
173.194.37.69
$ tor-resolve -v google.com
Nov 14 03:49:20.847 [debug] main(): defaulting to localhost
Nov 14 03:49:20.847 [debug] main(): defaulting to port 9050
173.194.37.69
$ tor-resolve -v google.com
Nov 14 03:49:21.089 [debug] main(): defaulting to localhost
Nov 14 03:49:21.089 [debug] main(): defaulting to port 9050
173.194.37.69
$ tor-resolve -v google.com
Nov 14 03:49:21.327 [debug] main(): defaulting to localhost
Nov 14 03:49:21.327 [debug] main(): defaulting to port 9050
173.194.37.69

What shall be done next to find the bug?

# tor-resolve --version
Tor version 0.2.3.25.
# tor --version
Tor version 0.2.5.1-alpha-dev (git-4aa9affec2eac0a9).

Answer 1

The problem was in my torrc, with:

VirtualAddrNetwork 192.168.0.0/8

My bad. This should be:

VirtualAddrNetwork 192.168.0.0/16

github.com is accurately 192.30.252.129

I enable the debug in torrc:

Log debug file /var/log/tor/debug.log

And, first success:

Feb 27 02:01:48.000 [debug] {APP} parse_socks(): socks5: fqdn address type
Feb 27 02:01:48.000 [debug] {APP} connection_ap_handshake_rewrite_and_attach(): Client asked for github.com:0
Feb 27 02:01:48.000 [debug] {CIRC,APP} connection_ap_handshake_attach_circuit(): Attaching apconn to circ 52054 (stream 0 sec old).
Feb 27 02:01:48.000 [info] {CIRC,APP} exit circ (length 3): FreeManning(open) 0nTorRamdiskOnly(open) UWashingtonCSE(open)
Feb 27 02:01:48.000 [debug] {CIRC,APP} link_apconn_to_circ(): attaching new conn to circ. n_circ_id 52054.
Feb 27 02:01:48.000 [info] {APP} link_apconn_to_circ(): Looks like completed circuit to $43822309763046C1621BFE7E811E886C6061E510=UWashingtonCSE at 128.208.2.233 does allow optimistic data for connection to github.com
Feb 27 02:01:48.000 [debug] {APP} connection_ap_handshake_send_resolve(): Sending relay cell to begin stream 63006.
Feb 27 02:01:48.000 [debug] {OR} relay_send_command_from_edge(): delivering 11 cell forward.

The second, after one second - Fails:

Feb 27 02:01:50.000 [debug] {NET} conn_read_callback(): socket 519 wants to read.
Feb 27 02:01:50.000 [debug] {NET} read_to_chunk(): Read 17 bytes. 17 on inbuf.
Feb 27 02:01:50.000 [debug] {APP} connection_ap_handshake_process_socks(): entered.
Feb 27 02:01:50.000 [debug] {APP} parse_socks(): socks5: checking request
Feb 27 02:01:50.000 [debug] {APP} parse_socks(): socks5: fqdn address type
Feb 27 02:01:50.000 [debug] {APP} connection_ap_handshake_rewrite_and_attach(): Client asked for github.com:0
Feb 27 02:01:50.000 [info] {APP} addressmap_rewrite(): Addressmap: rewriting "github.com" to "192.30.252.131"
Feb 27 02:01:50.000 [warn] {APP} Missing mapping for virtual address '192.30.252.131'. Refusing.
Feb 27 02:01:50.000 [debug] {NET} conn_close_if_marked(): Cleaning up connection (fd 519).

Third fails too:

Feb 27 02:01:51.000 [debug] {APP} connection_ap_handshake_rewrite_and_attach(): Client asked for github.com:0
Feb 27 02:01:51.000 [info] {APP} addressmap_rewrite(): Addressmap: rewriting "github.com" to "192.30.252.131"
Feb 27 02:01:51.000 [warn] {APP} Missing mapping for virtual address '192.30.252.131'. Refusing.

Etc, but after a minute, one success.

Another instance of Tor returns me github's IP any times at line.

---

I found answer directly in the source code:

 if (!automap && address_is_in_virtual_range(socks->address)) {
    /* This address was probably handed out by client_dns_get_unmapped_address,
     * but the mapping was discarded for some reason.  We *don't* want to send
     * the address through Tor; that's likely to fail, and may leak
     * information.
     */
    log_warn(LD_APP,"Missing mapping for virtual address '%s'. Refusing.",
             safe_str_client(socks->address));
    connection_mark_unattached_ap(conn, END_STREAM_REASON_INTERNAL);
    return -1;
  }

Check the declaration:

/* We set this to true if this is an address we should automatically
   * remap to a local address in VirtualAddrNetwork */
  int automap = 0;

However, in last source it looks little differently.

I found this https://gitweb.torproject.org/torspec.git/blob_plain/HEAD:/proposals/181-optimistic-data-client.txt

Looks like each minute my request was optimistic data.