Circuit dirtiness is inconsistant with MaxCircuitDirtiness
Hi,
I am experimenting some stuffs in Shadow and I am trying to have each circuit different for each begin cell sent. To achieve that, I have set up in my torrcs the following options:
SocksPort 127.0.0.1:9000 IsolateDestAddr MaxCircuitDirtiness 1
Which should pick a different circuit for each begin cell sent. However, sometimes a relay begin is sent over a previously used circuit. For example 2 begin cells sent over circuit 3592237881:
Jan 01 00:42:04.000 [info] int connection_handle_listener_read(connection_t *, int): New SOCKS connection opened from 127.0.0.1.
Jan 01 00:42:04.000 [info] exit circ (length 3): $75E3C46989B7DFD95D6C2078660D1FC3F04C175E(open) $11D472A45E4F39A07E0827CE7FAEF259D97242E1(open) $89C224C7F82640AD07B390A74957C5BF34B0B1D9(open)
Jan 01 00:42:04.000 [info] void link_apconn_to_circ(entry_connection_t *, origin_circuit_t *, crypt_path_t *): Looks like completed circuit to <skip>
Jan 01 00:42:04.000 [info] int connection_ap_handshake_send_begin(entry_connection_t *): Sending relay cell 0 on circ 3592237881 to begin stream 30786 with <skip>
Jan 01 00:42:04.000 [info] int connection_ap_handshake_send_begin(entry_connection_t *): Address/port sent, ap socket 4393, n_circ_id 3592237881
Jan 01 00:42:04.000 [info] int connection_edge_process_inbuf(edge_connection_t *, int): data from edge while in 'waiting for connect response' state. Leaving it on buffer.
Jan 01 00:42:05.000 [info] int connection_edge_process_relay_cell(cell_t *, circuit_t *, edge_connection_t *, crypt_path_t *): data cell dropped, unknown stream (streamid 14993).
Jan 01 00:42:05.000 [info] int connection_edge_process_relay_cell(cell_t *, circuit_t *, edge_connection_t *, crypt_path_t *): data cell dropped, unknown stream (streamid 14993).
Jan 01 00:42:05.000 [info] int connection_edge_process_relay_cell(cell_t *, circuit_t *, edge_connection_t *, crypt_path_t *): data cell dropped, unknown stream (streamid 14993).
Jan 01 00:42:05.000 [info] int connection_edge_process_relay_cell_not_open(relay_header_t *, cell_t *, circuit_t *, edge_connection_t *, crypt_path_t *): 'connected' <skip>
Jan 01 00:42:05.000 [info] exit circ (length 3): $75E3C46989B7DFD95D6C2078660D1FC3F04C175E(open) $11D472A45E4F39A07E0827CE7FAEF259D97242E1(open) $89C224C7F82640AD07B390A74957C5BF34B0B1D9(open)
Jan 01 00:42:06.000 [info] int connection_edge_process_relay_cell(cell_t *, circuit_t *, edge_connection_t *, crypt_path_t *): 4393: end cell (closed normally) for stream 30786. Removing stream.
Jan 01 00:42:13.000 [info] int connection_handle_listener_read(connection_t *, int): New SOCKS connection opened from 127.0.0.1.
Jan 01 00:42:13.000 [info] exit circ (length 3): $75E3C46989B7DFD95D6C2078660D1FC3F04C175E(open) $11D472A45E4F39A07E0827CE7FAEF259D97242E1(open) $89C224C7F82640AD07B390A74957C5BF34B0B1D9(open)
Jan 01 00:42:13.000 [info] void pathbias_count_use_attempt(origin_circuit_t *): Used circuit 53 is already in path state use succeeded. Circuit is a General-purpose client currently open.
Jan 01 00:42:13.000 [info] void link_apconn_to_circ(entry_connection_t *, origin_circuit_t *, crypt_path_t *): Looks like completed circuit to <skip>
Jan 01 00:42:13.000 [info] int connection_ap_handshake_send_begin(entry_connection_t *): Sending relay cell 0 on circ 3592237881 to begin stream 30787 with <skip>
Jan 01 00:42:13.000 [info] int connection_ap_handshake_send_begin(entry_connection_t *): Address/port sent, ap socket 4441, n_circ_id 3592237881
Several observations:
- It happens only for 2 begin cells containing same IP
- It happens only when the timing between them is close enough (here 9 seconds)
My guess is that function approx_time() used to setup the timestamp_dirty is very approximative (maybe related to Shadow?). circuit_is_acceptable() does not seems to reject this circuit as this code should do:
if (circ->timestamp_dirty &&
circ->timestamp_dirty+get_options()->MaxCircuitDirtiness <= now)
return 0;
variable "now" is containing the value returned by approx_time() instead of time(NULL) for performance reason.
So, this is not very much a problem but in my case, it bothers me.