Make refresh_keys more failsafe against dirmngr madness
tldr; If you try to refresh_keys over tor, it might be very unstable. We can make the process more robust against consequent failures.
Short summary:
Dirmngr tries to be "clever", actually it tries to be statefull where it should be stateless.
This might have the effect that once a connection to a keyserver fails it will never recover from such an error till for the whole refresh_keys run.
We can even be more "clever" than dirmngr and try to be more robust in case of a failure.
This is something that should be discussed upstream (gnupg), but the possible failure safety is still something that might make sense for schleuder.
Longer description:
Situation:
Looping over all gpg keys in a keyring and refreshing them. dirmngr is configured to use-tor and the keyserver is enforced to be the official onion service for it.
After certain amount of key fetches it can happen, that a connection is failing to the OS, the key update aborts AND dirmngr marks the keyserver-onion-service as dead, this results in the problem that any further key refresh is failing as well, as there are no more keyservers available. Dirmngr does not recover from that state until refresh "finished" and we kill dirmngr after the refresh. So on the next run the new refreshes are fine again until it fails again.
Tor observation:
Somehow the circuit gets closed and this aborts the current connection, which results in the connection error.
$ gpg --version
gpg (GnuPG) 2.2.3
libgcrypt 1.8.1
$ tor --version
Tor version 0.3.2.9 (git-9e8b762fcecfece6).
dirmngr.conf
use-tor
keyserver hkp://jirk5u4osbsr34t5.onion
dirmngr:
2018-01-24 00:07:12 dirmngr[30492.6] DBG: chan_6 -> OK
2018-01-24 00:07:12 dirmngr[30492.6] DBG: chan_6 <- KEYSERVER
2018-01-24 00:07:12 dirmngr[30492.6] DBG: chan_6 -> S KEYSERVER hkp://jirk5u4osbsr34t5.onion
2018-01-24 00:07:12 dirmngr[30492.6] DBG: chan_6 -> OK
2018-01-24 00:07:12 dirmngr[30492.6] DBG: chan_6 <- KS_GET -- 0xDEADBEEF
2018-01-24 00:07:12 dirmngr[30492.6] DBG: http.c:connect_server:onion: name='jirk5u4osbsr34t5.onion' port=11371
2018-01-24 00:07:14 dirmngr[30492.6] can't connect to 'jirk5u4osbsr34t5.onion': Network is down
2018-01-24 00:07:14 dirmngr[30492.6] error connecting to 'http://jirk5u4osbsr34t5.onion:11371': Network is down
2018-01-24 00:07:14 dirmngr[30492.6] marking host 'jirk5u4osbsr34t5.onion' as dead
2018-01-24 00:07:14 dirmngr[30492.6] host 'jirk5u4osbsr34t5.onion' marked as dead
2018-01-24 00:07:14 dirmngr[30492.6] command 'KS_GET' failed: No keyserver available
2018-01-24 00:07:14 dirmngr[30492.6] DBG: chan_6 -> ERR 167772346 No keyserver available <Dirmngr>
2018-01-24 00:07:14 dirmngr[30492.6] DBG: chan_6 <- BYE
2018-01-24 00:07:14 dirmngr[30492.6] DBG: chan_6 -> OK closing connection
2018-01-24 00:07:14 dirmngr[30492.6] handler for fd 6 terminated
2018-01-24 00:07:19 dirmngr[30492.6] handler for fd 6 started
2018-01-24 00:07:19 dirmngr[30492.6] DBG: chan_6 -> # Home: /var/lib/schleuder/lists/example.com/info
2018-01-24 00:07:19 dirmngr[30492.6] DBG: chan_6 -> # Config: /var/lib/schleuder/lists/example.com/info/dirmngr.conf
2018-01-24 00:07:19 dirmngr[30492.6] DBG: chan_6 -> OK Dirmngr 2.2.3 at your service
2018-01-24 00:07:19 dirmngr[30492.6] connection from process 18139 (995:992)
2018-01-24 00:07:19 dirmngr[30492.6] DBG: chan_6 <- GETINFO version
2018-01-24 00:07:19 dirmngr[30492.6] DBG: chan_6 -> D 2.2.3
2018-01-24 00:07:19 dirmngr[30492.6] DBG: chan_6 -> OK
2018-01-24 00:07:19 dirmngr[30492.6] DBG: chan_6 <- KEYSERVER --clear hkp://jirk5u4osbsr34t5.onion
2018-01-24 00:07:19 dirmngr[30492.6] DBG: chan_6 -> OK
2018-01-24 00:07:19 dirmngr[30492.6] DBG: chan_6 <- KEYSERVER
2018-01-24 00:07:19 dirmngr[30492.6] DBG: chan_6 -> S KEYSERVER hkp://jirk5u4osbsr34t5.onion
2018-01-24 00:07:19 dirmngr[30492.6] DBG: chan_6 -> OK
2018-01-24 00:07:19 dirmngr[30492.6] DBG: chan_6 <- KS_GET -- 0xFACEB00
2018-01-24 00:07:19 dirmngr[30492.6] host 'jirk5u4osbsr34t5.onion' marked as dead
2018-01-24 00:07:19 dirmngr[30492.6] command 'KS_GET' failed: No keyserver available
2018-01-24 00:07:19 dirmngr[30492.6] DBG: chan_6 -> ERR 167772346 No keyserver available <Dirmngr>
2018-01-24 00:07:19 dirmngr[30492.6] DBG: chan_6 <- BYE
2018-01-24 00:07:19 dirmngr[30492.6] DBG: chan_6 -> OK closing connection
2018-01-24 00:07:19 dirmngr[30492.6] handler for fd 6 terminated
2018-01-24 00:07:20 dirmngr[30492.6] handler for fd 6 started
tor debug:
Relevant part:
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] connection_bucket_refill_helper(): global_write_bucket now 1073741824.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] connection_bucket_refill_helper(): or_conn->write_bucket now 1073741824.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] conn_read_callback(): socket 10 wants to read.
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] connection_buf_read_from_socket(): 10: starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] connection_buf_read_from_socket(): After TLS read of 514: 543 read, 0 written
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] connection_or_process_cells_from_inbuf(): 10: starting, inbuf_datalen 514 (0 pending in tls object).
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] channel_queue_cell(): Directly handling incoming cell_t 0x7fffdcb2bb20 for channel 0x558bb0968700 (global ID 1)
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x558bb096db50 for circ_id 3753591321, channel ID 1 (0x558bb0968700)
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] circuit_receive_relay_cell(): Sending to origin.
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] connection_edge_process_relay_cell(): Now seen 2757 relay cells here (command 9, stream 0).
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x558bb096db50 for circ_id 3753591321, channel ID 1 (0x558bb0968700)
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] pathbias_count_use_success(): Marked circuit 17 (4.000000/4.000000) as used successfully for guard kerly ($3BB035514F8246AC367B5370F4FE120BB11D8C6D)
/var/log/tor/debug.log:Jan 24 00:07:13.000 [info] circuit_mark_for_close_(): Circuit 3753591321 (id: 17) marked for close at src/or/circuitbuild.c:1543 (orig reason: 512, new reason: 0)
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] connection_or_process_cells_from_inbuf(): 10: starting, inbuf_datalen 0 (0 pending in tls object).
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] connection_bucket_refill_helper(): global_read_bucket now 1073741824.
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] connection_bucket_refill_helper(): or_conn->read_bucket now 1073741824.
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x558bb096db50 for circ_id 3753591321, channel ID 1 (0x558bb0968700)
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] circuitmux_append_destroy_cell(): Cmux at 0x558bb096a3b0 queued a destroy for circ 3753591321, cmux counter is now 1, global counter is now 1
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] circuitmux_append_destroy_cell(): Primed a buffer.
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] channel_write_cell_generic_(): Writing p 0x558bb09ab7f0 to channel 0x558bb0968700 with global ID 1
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x558bb096db50 for circ_id 3753591321, channel ID 1 (0x558bb0968700)
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] channel_tls_get_overhead_estimate_method(): Estimated overhead ratio for TLS chan 1 is 1.053876
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] channel_update_xmit_queue_size(): Increasing queue size for channel 1 by 541 from 0 to 541
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] channel_update_xmit_queue_size(): Increasing global queue size by 541 for channel 1, new size is 541
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] circuitmux_notify_xmit_destroy(): Cmux at 0x558bb096a3b0 sent a destroy, cmux counter is now 0, global counter is now 0
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] channel_send_destroy(): Sending destroy (circID 3753591321) on channel 0x558bb0968700 (global ID 1)
/var/log/tor/debug.log:Jan 24 00:07:14.000 [info] connection_edge_destroy(): CircID 0: At an edge. Marking connection for close.
/var/log/tor/debug.log:Jan 24 00:07:14.000 [info] rend_client_note_connection_attempt_ended(): Connection attempt for [scrubbed] has ended; cleaning up temporary state.
/var/log/tor/debug.log:Jan 24 00:07:14.000 [info] circuit_free(): Circuit 0 (id: 17) has been freed.
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] conn_close_if_marked(): Cleaning up connection (fd 11).
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] connection_remove(): removing socket 11 (type Socks), n_conns now 3
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] connection_free_(): closing fd 11.
more logs
/var/log/tor/debug.log:Jan 24 00:07:10.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
/var/log/tor/debug.log:Jan 24 00:07:11.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] conn_read_callback(): socket 6 wants to read.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] connection_handle_listener_read(): Connection accepted on socket 11 (child of fd 6).
/var/log/tor/debug.log:Jan 24 00:07:12.000 [info] connection_handle_listener_read(): New SOCKS connection opened from 127.0.0.1.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] connection_add_impl(): new conn type Socks, socket 11, address 127.0.0.1, n_conns 3.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] conn_read_callback(): socket 11 wants to read.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] read_to_chunk(): Read 3 bytes. 3 on inbuf.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] connection_ap_handshake_process_socks(): entered.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] parse_socks(): socks5: accepted method 0 (no authentication)
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] connection_ap_handshake_process_socks(): socks handshake not all here yet.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] connection_ap_handshake_process_socks(): entered.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] connection_ap_handshake_process_socks(): socks handshake not all here yet.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] conn_write_callback(): socket 11 wants to write.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] conn_read_callback(): socket 11 wants to read.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] read_to_chunk(): Read 29 bytes. 29 on inbuf.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] connection_ap_handshake_process_socks(): entered.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] parse_socks(): socks5: checking request
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] parse_socks(): socks5: fqdn address type
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] connection_ap_handshake_rewrite(): Client asked for [scrubbed]:11371
/var/log/tor/debug.log:Jan 24 00:07:12.000 [info] connection_ap_handle_onion(): Got a hidden service request for ID '[scrubbed]'
/var/log/tor/debug.log:Jan 24 00:07:12.000 [info] rep_hist_note_used_internal(): New port prediction added. Will continue predictive circ building for 3110 more seconds.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [info] connection_ap_handle_onion(): Descriptor is here. Great.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for circuit' state. Leaving it on buffer.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [info] connection_ap_handshake_attach_circuit(): rend joined circ 3753591321 (id: 17) already here. Attaching. (stream 0 sec old)
/var/log/tor/debug.log:Jan 24 00:07:12.000 [info] pathbias_count_use_attempt(): Used circuit 17 is already in path state use succeeded. Circuit is a Hidden service client: Active rendezvous point currently open.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] link_apconn_to_circ(): attaching new conn to circ. n_circ_id 3753591321.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [info] rend_client_note_connection_attempt_ended(): Connection attempt for [scrubbed] has ended; cleaning up temporary state.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [info] link_apconn_to_circ(): Looks like completed circuit to hidden service does allow optimistic data for connection to [scrubbed]
/var/log/tor/debug.log:Jan 24 00:07:12.000 [info] connection_ap_handshake_send_begin(): Sending relay cell 0 on circ 3753591321 to begin stream 54859.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] relay_send_command_from_edge_(): delivering 1 cell forward.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] circuit_package_relay_cell(): encrypting a layer of the relay cell.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] circuit_package_relay_cell(): encrypting a layer of the relay cell.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] circuit_package_relay_cell(): encrypting a layer of the relay cell.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] circuit_package_relay_cell(): encrypting a layer of the relay cell.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] append_cell_to_circuit_queue(): Made a circuit active.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] scheduler_channel_has_waiting_cells(): Channel 1 at 0x558bb0968700 went from waiting_for_cells to pending
/var/log/tor/debug.log:Jan 24 00:07:12.000 [info] connection_ap_handshake_send_begin(): Address/port sent, ap socket 11, n_circ_id 3753591321
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] scheduler_evt_callback(): Scheduler event callback called
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] update_socket_info(): chan=1 updated socket info, limit: 25960, cwnd: 10, unacked: 0, notsent: 0, mss: 1298
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] kist_scheduler_run(): Running the scheduler. 1 channels pending
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] outbuf_table_add(): scheduler init outbuf info for chan=1
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] channel_tls_get_overhead_estimate_method(): Estimated overhead ratio for TLS chan 1 is 1.053872
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] channel_write_cell_generic_(): Writing p 0x558bb09ab7f0 to channel 0x558bb0968700 with global ID 1
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] channel_tls_get_overhead_estimate_method(): Estimated overhead ratio for TLS chan 1 is 1.053872
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] channel_update_xmit_queue_size(): Increasing queue size for channel 1 by 541 from 0 to 541
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] channel_update_xmit_queue_size(): Increasing global queue size by 541 for channel 1, new size is 541
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] channel_flush_from_first_active_circuit(): Made a circuit inactive.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] update_socket_written(): chan=1 wrote 543 bytes, old was 0
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] kist_scheduler_run(): chan=1 now waiting_for_cells
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] channel_write_to_kernel(): Writing 514 bytes to kernel for chan 1
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] flush_chunk_tls(): flushed 514 bytes, 0 ready to flush, 0 remain.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] connection_handle_write_impl(): After TLS write of 514: 0 read, 543 written
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] channel_tls_get_overhead_estimate_method(): Estimated overhead ratio for TLS chan 1 is 1.053876
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] channel_update_xmit_queue_size(): Decreasing queue size for channel 1 by 541 from 541 to 0
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] channel_update_xmit_queue_size(): Decreasing global queue size by 541 for channel 1, new size is 0
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] free_outbuf_info_by_ent(): Freeing outbuf table entry from chan=1
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] kist_scheduler_run(): len pending=0, len to_readd=-1
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] connection_bucket_refill_helper(): global_write_bucket now 1073741824.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] connection_bucket_refill_helper(): or_conn->write_bucket now 1073741824.
/var/log/tor/debug.log:Jan 24 00:07:12.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] conn_read_callback(): socket 10 wants to read.
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] connection_buf_read_from_socket(): 10: starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] connection_buf_read_from_socket(): After TLS read of 514: 543 read, 0 written
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] connection_or_process_cells_from_inbuf(): 10: starting, inbuf_datalen 514 (0 pending in tls object).
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] channel_queue_cell(): Directly handling incoming cell_t 0x7fffdcb2bb20 for channel 0x558bb0968700 (global ID 1)
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x558bb096db50 for circ_id 3753591321, channel ID 1 (0x558bb0968700)
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] circuit_receive_relay_cell(): Sending to origin.
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] connection_edge_process_relay_cell(): Now seen 2757 relay cells here (command 9, stream 0).
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x558bb096db50 for circ_id 3753591321, channel ID 1 (0x558bb0968700)
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] pathbias_count_use_success(): Marked circuit 17 (4.000000/4.000000) as used successfully for guard kerly ($3BB035514F8246AC367B5370F4FE120BB11D8C6D)
/var/log/tor/debug.log:Jan 24 00:07:13.000 [info] circuit_mark_for_close_(): Circuit 3753591321 (id: 17) marked for close at src/or/circuitbuild.c:1543 (orig reason: 512, new reason: 0)
/var/log/tor/debug.log:Jan 24 00:07:13.000 [debug] connection_or_process_cells_from_inbuf(): 10: starting, inbuf_datalen 0 (0 pending in tls object).
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] connection_bucket_refill_helper(): global_read_bucket now 1073741824.
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] connection_bucket_refill_helper(): or_conn->read_bucket now 1073741824.
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x558bb096db50 for circ_id 3753591321, channel ID 1 (0x558bb0968700)
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] circuitmux_append_destroy_cell(): Cmux at 0x558bb096a3b0 queued a destroy for circ 3753591321, cmux counter is now 1, global counter is now 1
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] circuitmux_append_destroy_cell(): Primed a buffer.
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] channel_write_cell_generic_(): Writing p 0x558bb09ab7f0 to channel 0x558bb0968700 with global ID 1
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x558bb096db50 for circ_id 3753591321, channel ID 1 (0x558bb0968700)
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] channel_tls_get_overhead_estimate_method(): Estimated overhead ratio for TLS chan 1 is 1.053876
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] channel_update_xmit_queue_size(): Increasing queue size for channel 1 by 541 from 0 to 541
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] channel_update_xmit_queue_size(): Increasing global queue size by 541 for channel 1, new size is 541
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] circuitmux_notify_xmit_destroy(): Cmux at 0x558bb096a3b0 sent a destroy, cmux counter is now 0, global counter is now 0
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] channel_send_destroy(): Sending destroy (circID 3753591321) on channel 0x558bb0968700 (global ID 1)
/var/log/tor/debug.log:Jan 24 00:07:14.000 [info] connection_edge_destroy(): CircID 0: At an edge. Marking connection for close.
/var/log/tor/debug.log:Jan 24 00:07:14.000 [info] rend_client_note_connection_attempt_ended(): Connection attempt for [scrubbed] has ended; cleaning up temporary state.
/var/log/tor/debug.log:Jan 24 00:07:14.000 [info] circuit_free(): Circuit 0 (id: 17) has been freed.
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] conn_close_if_marked(): Cleaning up connection (fd 11).
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] connection_remove(): removing socket 11 (type Socks), n_conns now 3
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] connection_free_(): closing fd 11.
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] conn_write_callback(): socket 10 wants to write.
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] flush_chunk_tls(): flushed 514 bytes, 0 ready to flush, 0 remain.
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] connection_handle_write_impl(): After TLS write of 514: 0 read, 543 written
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] channel_tls_get_overhead_estimate_method(): Estimated overhead ratio for TLS chan 1 is 1.053881
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] channel_update_xmit_queue_size(): Decreasing queue size for channel 1 by 541 from 541 to 0
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] channel_update_xmit_queue_size(): Decreasing global queue size by 541 for channel 1, new size is 0
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] connection_bucket_refill_helper(): global_write_bucket now 1073741824.
/var/log/tor/debug.log:Jan 24 00:07:14.000 [debug] connection_bucket_refill_helper(): or_conn->write_bucket now 1073741824.
/var/log/tor/debug.log:Jan 24 00:07:15.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
/var/log/tor/debug.log:Jan 24 00:07:16.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
/var/log/tor/debug.log:Jan 24 00:07:17.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
/var/log/tor/debug.log:Jan 24 00:07:18.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.
/var/log/tor/debug.log:Jan 24 00:07:18.000 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 1 to [scrubbed] ([scrubbed]) after 4209 ms. Delta 1ms
/var/log/tor/debug.log:Jan 24 00:07:18.000 [debug] conn_write_callback(): socket 10 wants to write.
/var/log/tor/debug.log:Jan 24 00:07:18.000 [debug] flush_chunk_tls(): flushed 514 bytes, 0 ready to flush, 0 remain.
/var/log/tor/debug.log:Jan 24 00:07:18.000 [debug] connection_handle_write_impl(): After TLS write of 514: 0 read, 543 written
/var/log/tor/debug.log:Jan 24 00:07:18.000 [debug] channel_tls_get_overhead_estimate_method(): Estimated overhead ratio for TLS chan 1 is 1.053885
/var/log/tor/debug.log:Jan 24 00:07:18.000 [debug] connection_bucket_refill_helper(): global_write_bucket now 1073741824.
/var/log/tor/debug.log:Jan 24 00:07:18.000 [debug] connection_bucket_refill_helper(): or_conn->write_bucket now 1073741824.
/var/log/tor/debug.log:Jan 24 00:07:19.000 [debug] circuit_remove_handled_ports(): Port 443 is already being handled; removing.