Skip to content

Tor hanging in early in bootstrapping, not leaving main loop

Summary

Sometimes, Tor (on Android) hangs in bootstrapping and does not continue even if waiting for a long time. Easier to reproduce by cleaning all filesystem state. No more log output, not even DEBUG debug events get logged over the control connection.

Steps to reproduce:

  1. Download or compile Onionshare for Android: https://github.com/onionshare/onionshare-android
  2. Clear all app data
  3. Share a file
  4. Hope for progress bar and logcat output to hang
  5. If not, go back to 2.

What is the current bug behavior?

Tor doesn't exit main loop, doesn't bootstrap and just hangs.

What is the expected behavior?

Tor bootstraps.

Environment

  • Which version of Tor are you using? 0.4.6.8
  • Which operating system are you using? Android via tor-android library from GuardianProject
  • Which installation method did you use? Built into OnionShare app

Relevant logs and/or screenshots

2022-02-01 17:32:41.955 D: DEBUG: conn_read_callback: socket -1 wants to read.
2022-02-01 17:32:41.955 D: DEBUG: connection_dir_process_inbuf: Got data, not eof. Leaving on inbuf.
2022-02-01 17:32:41.955 D: DEBUG: sendme_connection_edge_consider_sending: Outbuf 0, queuing stream SENDME.
2022-02-01 17:32:41.956 D: DEBUG: relay_send_command_from_edge_: delivering 5 cell forward.
2022-02-01 17:32:41.956 D: DEBUG: relay_encrypt_cell_outbound: encrypting a layer of the relay cell.
2022-02-01 17:32:41.956 D: DEBUG: conn_read_callback: socket 75 wants to read.
2022-02-01 17:32:41.956 D: DEBUG: connection_buf_read_from_socket: 75: starting, inbuf_datalen 258 (0 pending in tls object). at_most 2072.
2022-02-01 17:32:41.956 D: DEBUG: tor_tls_read: read returned r=-1, err=-2
2022-02-01 17:32:41.956 D: DEBUG: connection_buf_read_from_socket: After TLS read of 770: 3100 read, 0 written
2022-02-01 17:32:41.956 D: DEBUG: connection_or_process_cells_from_inbuf: 75: starting, inbuf_datalen 1028 (0 pending in tls object).
2022-02-01 17:32:41.956 D: DEBUG: channel_process_cell: Processing incoming cell_t 0x7101bb2658 for channel 0xb40000725ab36a00 (global ID 5)
2022-02-01 17:32:41.956 D: DEBUG: circuit_get_by_circid_channel_impl: circuit_get_by_circid_channel_impl() returning circuit 0xb40000725ab377e0 for circ_id 2917690044, channel ID 5 (0xb40000725ab36a00)
2022-02-01 17:32:41.956 D: DEBUG: relay_lookup_conn: found conn for stream 173.
2022-02-01 17:32:41.956 D: DEBUG: circuit_receive_relay_cell: Sending to origin.
2022-02-01 17:32:41.956 D: DEBUG: connection_edge_process_relay_cell: Now seen 1845 relay cells here (command 2, stream 173).
2022-02-01 17:32:41.956 D: DEBUG: sendme_circuit_data_received: Circuit deliver_window now 965.
2022-02-01 17:32:41.956 D: DEBUG: connection_or_process_cells_from_inbuf: 75: starting, inbuf_datalen 514 (0 pending in tls object).
2022-02-01 17:32:41.956 D: DEBUG: channel_process_cell: Processing incoming cell_t 0x7101bb2658 for channel 0xb40000725ab36a00 (global ID 5)
2022-02-01 17:32:41.957 D: DEBUG: circuit_get_by_circid_channel_impl: circuit_get_by_circid_channel_impl() returning circuit 0xb40000725ab377e0 for circ_id 2917690044, channel ID 5 (0xb40000725ab36a00)
2022-02-01 17:32:41.957 D: DEBUG: relay_lookup_conn: found conn for stream 173.
2022-02-01 17:32:41.957 D: DEBUG: circuit_receive_relay_cell: Sending to origin.
2022-02-01 17:32:41.957 D: DEBUG: connection_edge_process_relay_cell: Now seen 1846 relay cells here (command 2, stream 173).
2022-02-01 17:32:41.957 D: DEBUG: sendme_circuit_data_received: Circuit deliver_window now 964.
2022-02-01 17:32:41.957 D: DEBUG: connection_or_process_cells_from_inbuf: 75: starting, inbuf_datalen 0 (0 pending in tls object).
2022-02-01 17:32:41.957 D: DEBUG: conn_read_callback: socket -1 wants to read.
2022-02-01 17:32:41.957 D: DEBUG: connection_dir_client_reached_eof: Downloaded 171820 bytes on connection of purpose microdescriptor fetch; bootstrap 50%
2022-02-01 17:32:41.957 D: DEBUG: fetch_from_buf_http: headerlen 194, bodylen 171626.
2022-02-01 17:32:41.957 D: DEBUG: Received response on Directory connection (client reading) with 144.202.49.171:9001: 200 "OK" (purpose: 19, response size: 171820, compression: 4)
2022-02-01 17:32:41.957 D: INFO: make_guard_confirmed: Marking dongusvondong ($E9A90B9FF0574410695BA5F5C8354368221A7114) as a confirmed guard (index 0)
2022-02-01 17:32:41.957 D: INFO: entry_guards_update_primary: Primary entry guards have changed. New primary guard list is:
2022-02-01 17:32:41.957 D: INFO: entry_guards_update_primary:   1/3: dongusvondong ($E9A90B9FF0574410695BA5F5C8354368221A7114) (confirmed)
2022-02-01 17:32:41.957 D: INFO: entry_guards_update_primary:   2/3: digitalResistanceRu ($841DE1E065BCA8C1EBDC4A7140646F47A6257BD8)
2022-02-01 17:32:41.958 D: INFO: entry_guards_update_primary:   3/3: WonderWoman42 ($6D8DA81B9572023472C47B16E30D6A882B896B4E)
2022-02-01 17:32:41.958 D: INFO: entry_guards_note_guard_success: Recorded success for primary confirmed guard dongusvondong ($E9A90B9FF0574410695BA5F5C8354368221A7114)
2022-02-01 17:32:41.958 D: DEBUG: connection_dir_client_reached_eof: Time on received directory is within tolerance; we are -3 seconds skewed.  (That's okay.)
2022-02-01 17:32:41.958 D: DEBUG: HTTP body from Directory connection (client reading) with 144.202.49.171:9001 was labeled as Zstandard compressed, and it seems to be Zstandard compressed.
2022-02-01 17:32:41.958 D: INFO: handle_response_fetch_microdesc: Received answer to microdescriptor request (status 200, body size 670229) from server 144.202.49.171:9001
2022-02-01 17:32:41.958 D: DEBUG: count_usable_descriptors: 6845 usable, 500 present (microdescs).
2022-02-01 17:32:41.958 D: DEBUG: compute_frac_paths_available: mid: 0 present, 0 usable
2022-02-01 17:32:41.958 D: DEBUG: compute_frac_paths_available: guard: 3913 possible
2022-02-01 17:32:41.958 D: DEBUG: count_usable_descriptors: 1389 usable, 96 present (microdesc exit policies and flags).
2022-02-01 17:32:41.958 D: DEBUG: compute_frac_paths_available: exits: 96 present, 1389 usable
2022-02-01 17:32:41.958 D: DEBUG: compute_weighted_bandwidths: Generated weighted bandwidths for rule weight as guard based on weights Wg=0.600700 Wm=0.600700 We=0.000000 Wd=0.000000 with total bw 33039303135.900002
2022-02-01 17:32:41.958 D: DEBUG: compute_weighted_bandwidths: Generated weighted bandwidths for rule weight as middle node based on weights Wg=0.399300 Wm=1.000000 We=0.000000 Wd=0.000000 with total bw 33038899864.099998
2022-02-01 17:32:41.959 D: DEBUG: compute_weighted_bandwidths: Generated weighted bandwidths for rule weight as exit based on weights Wg=1.000000 Wm=1.000000 We=1.000000 Wd=1.000000 with total bw 27523872000.000000
2022-02-01 17:32:41.959 D: DEBUG: compute_frac_paths_available: f_guard: 0.08, f_mid: 0.09, f_exit: 0.07
2022-02-01 17:32:41.959 D: DEBUG: update_guard_selection_choice: Staying with guard context "default" (no change)
2022-02-01 17:32:41.959 D: INFO: sampled_guards_update_from_consensus: Updating sampled guard status based on received consensus.
2022-02-01 17:32:41.959 D: DEBUG: sampled_guards_update_consensus_presence: Sampled guard digitalResistanceRu ($841DE1E065BCA8C1EBDC4A7140646F47A6257BD8) is still listed.
2022-02-01 17:32:41.959 D: DEBUG: sampled_guards_update_consensus_presence: Sampled guard WonderWoman42 ($6D8DA81B9572023472C47B16E30D6A882B896B4E) is still listed.
2022-02-01 17:32:41.959 D: DEBUG: sampled_guards_update_consensus_presence: Sampled guard dongusvondong ($E9A90B9FF0574410695BA5F5C8354368221A7114) is still listed.
2022-02-01 17:32:41.959 D: DEBUG: sampled_guards_update_consensus_presence: Sampled guard lotsaSquirrels ($CFF88D79C485653DBECCC0EA1474E975EDAB5D45) is still listed.
2022-02-01 17:32:41.959 D: DEBUG: sampled_guards_update_consensus_presence: Sampled guard Init6TorRelay ($A22B1C2EF2255987F8AB8AA0B1A8E23F5023EEB8) is still listed.
2022-02-01 17:32:41.959 D: DEBUG: sampled_guards_update_consensus_presence: Sampled guard Fission11 ($929BB84A68198CE35E2F2828812840AF5C2CBC4A) is still listed.
2022-02-01 17:32:41.959 D: DEBUG: sampled_guards_update_consensus_presence: Sampled guard reallyniceplace ($049852A10805835E9AB2C551D6C438BE6DE8B24C) is still listed.
2022-02-01 17:32:41.959 D: DEBUG: sampled_guards_update_consensus_presence: Sampled guard dr167 ($9ED8E45D2C666F019C17F23FF567E9EB1E7DADB8) is still listed.
2022-02-01 17:32:41.959 D: DEBUG: sampled_guards_update_consensus_presence: Sampled guard Unnamed ($A56A0120A21557832000D5C68FCD7DE08E82A3B0) is still listed.
2022-02-01 17:32:41.959 D: DEBUG: sampled_guards_update_consensus_presence: Sampled guard torrx ($772D509772071D3082BAAF1C781C8F917013F3CB) is still listed.
2022-02-01 17:32:41.960 D: DEBUG: sampled_guards_update_consensus_presence: Sampled guard Piratenpartei08 ($E8965A79FB2F335194141E8968755524840C44B6) is still listed.
2022-02-01 17:32:41.960 D: DEBUG: sampled_guards_update_consensus_presence: Sampled guard zwiebeltoralf ($63BF46A63F9C21FD315CD061B3EAA3EB05283A0A) is still listed.
2022-02-01 17:32:41.960 D: DEBUG: sampled_guards_update_consensus_presence: Sampled guard MIGHTYWANG ($9B2BC7EFD661072AFADC533BE8DCF1C19D8C2DCC) is still listed.
2022-02-01 17:32:41.960 D: DEBUG: sampled_guards_update_consensus_presence: Sampled guard falared ($7EB91FDB68EAD3A13808D9356DA82605773215F5) is still listed.
2022-02-01 17:32:41.960 D: DEBUG: sampled_guards_update_consensus_presence: Sampled guard Chenjesu ($5DB9AE27A44EB7B476CC04A66C67A71C97A001E6) is still listed.
2022-02-01 17:32:41.960 D: DEBUG: sampled_guards_update_consensus_presence: Sampled guard Route66 ($0CE3B73DDFF92FF6653A9C7F9003A32BB6C2364D) is still listed.
2022-02-01 17:32:41.960 D: DEBUG: sampled_guards_update_consensus_presence: Sampled guard cosimaniehaus ($24F97F98C45E4754655BE66799049763DAEE99CE) is still listed.
2022-02-01 17:32:41.960 D: DEBUG: sampled_guards_update_consensus_presence: Sampled guard inconnu3 ($3ECAF1EAA2EE2C6A3DD191C820788C93386C24F9) is still listed.
2022-02-01 17:32:41.960 D: DEBUG: sampled_guards_update_consensus_presence: Sampled guard tirz ($124948FDBA0B63F23A2FB7DFC7DF62ED499DE546) is still listed.
2022-02-01 17:32:41.960 D: DEBUG: sampled_guards_update_consensus_presence: Sampled guard bonjour1 ($D80EA21626BFAE8044E4037FE765252E157E3586) is still listed.
2022-02-01 17:32:41.960 D: DEBUG: entry_guard_set_filtered_flags: Updated sampled guard digitalResistanceRu ($841DE1E065BCA8C1EBDC4A7140646F47A6257BD8): filtered=1; reachable_filtered=1.
2022-02-01 17:32:41.961 D: DEBUG: entry_guard_set_filtered_flags: Updated sampled guard WonderWoman42 ($6D8DA81B9572023472C47B16E30D6A882B896B4E): filtered=1; reachable_filtered=1.
2022-02-01 17:32:41.961 D: DEBUG: entry_guard_set_filtered_flags: Updated sampled guard dongusvondong ($E9A90B9FF0574410695BA5F5C8354368221A7114): filtered=1; reachable_filtered=1.
2022-02-01 17:32:41.961 D: DEBUG: entry_guard_set_filtered_flags: Updated sampled guard lotsaSquirrels ($CFF88D79C485653DBECCC0EA1474E975EDAB5D45): filtered=1; reachable_filtered=1.
2022-02-01 17:32:41.961 D: DEBUG: entry_guard_set_filtered_flags: Updated sampled guard Init6TorRelay ($A22B1C2EF2255987F8AB8AA0B1A8E23F5023EEB8): filtered=1; reachable_filtered=1.
2022-02-01 17:32:41.961 D: DEBUG: entry_guard_set_filtered_flags: Updated sampled guard Fission11 ($929BB84A68198CE35E2F2828812840AF5C2CBC4A): filtered=1; reachable_filtered=1.
2022-02-01 17:32:41.961 D: DEBUG: entry_guard_set_filtered_flags: Updated sampled guard reallyniceplace ($049852A10805835E9AB2C551D6C438BE6DE8B24C): filtered=1; reachable_filtered=1.
2022-02-01 17:32:41.961 D: DEBUG: entry_guard_set_filtered_flags: Updated sampled guard dr167 ($9ED8E45D2C666F019C17F23FF567E9EB1E7DADB8): filtered=1; reachable_filtered=1.
2022-02-01 17:32:41.961 D: DEBUG: entry_guard_set_filtered_flags: Updated sampled guard Unnamed ($A56A0120A21557832000D5C68FCD7DE08E82A3B0): filtered=1; reachable_filtered=1.
2022-02-01 17:32:41.961 D: DEBUG: entry_guard_set_filtered_flags: Updated sampled guard torrx ($772D509772071D3082BAAF1C781C8F917013F3CB): filtered=1; reachable_filtered=1.
2022-02-01 17:32:41.961 D: DEBUG: entry_guard_set_filtered_flags: Updated sampled guard Piratenpartei08 ($E8965A79FB2F335194141E8968755524840C44B6): filtered=1; reachable_filtered=1.
2022-02-01 17:32:41.961 D: DEBUG: entry_guard_set_filtered_flags: Updated sampled guard zwiebeltoralf ($63BF46A63F9C21FD315CD061B3EAA3EB05283A0A): filtered=1; reachable_filtered=1.
2022-02-01 17:32:41.961 D: DEBUG: entry_guard_set_filtered_flags: Updated sampled guard MIGHTYWANG ($9B2BC7EFD661072AFADC533BE8DCF1C19D8C2DCC): filtered=1; reachable_filtered=1.
2022-02-01 17:32:41.961 D: DEBUG: entry_guard_set_filtered_flags: Updated sampled guard falared ($7EB91FDB68EAD3A13808D9356DA82605773215F5): filtered=1; reachable_filtered=1.
2022-02-01 17:32:41.961 D: DEBUG: entry_guard_set_filtered_flags: Updated sampled guard Chenjesu ($5DB9AE27A44EB7B476CC04A66C67A71C97A001E6): filtered=1; reachable_filtered=1.
2022-02-01 17:32:41.962 D: DEBUG: entry_guard_set_filtered_flags: Updated sampled guard Route66 ($0CE3B73DDFF92FF6653A9C7F9003A32BB6C2364D): filtered=1; reachable_filtered=1.
2022-02-01 17:32:41.962 D: DEBUG: entry_guard_set_filtered_flags: Updated sampled guard cosimaniehaus ($24F97F98C45E4754655BE66799049763DAEE99CE): filtered=1; reachable_filtered=1.
2022-02-01 17:32:41.962 D: DEBUG: entry_guard_set_filtered_flags: Updated sampled guard inconnu3 ($3ECAF1EAA2EE2C6A3DD191C820788C93386C24F9): filtered=1; reachable_filtered=1.
2022-02-01 17:32:41.962 D: DEBUG: entry_guard_set_filtered_flags: Updated sampled guard tirz ($124948FDBA0B63F23A2FB7DFC7DF62ED499DE546): filtered=1; reachable_filtered=1.
2022-02-01 17:32:41.962 D: DEBUG: entry_guard_set_filtered_flags: Updated sampled guard bonjour1 ($D80EA21626BFAE8044E4037FE765252E157E3586): filtered=1; reachable_filtered=1.
2022-02-01 17:32:41.962 D: INFO: entry_guards_update_primary: Primary entry guards have changed. New primary guard list is:
2022-02-01 17:32:41.962 D: INFO: entry_guards_update_primary:   1/3: dongusvondong ($E9A90B9FF0574410695BA5F5C8354368221A7114) (confirmed)
2022-02-01 17:32:41.962 D: INFO: entry_guards_update_primary:   2/3: digitalResistanceRu ($841DE1E065BCA8C1EBDC4A7140646F47A6257BD8)
2022-02-01 17:32:41.962 D: INFO: entry_guards_update_primary:   3/3: WonderWoman42 ($6D8DA81B9572023472C47B16E30D6A882B896B4E)
2022-02-01 17:32:41.962 D: DEBUG: count_usable_descriptors: 6845 usable, 500 present (microdescs).
2022-02-01 17:32:41.962 D: DEBUG: compute_frac_paths_available: mid: 0 present, 0 usable
2022-02-01 17:32:41.962 D: DEBUG: compute_frac_paths_available: guard: 3913 possible
2022-02-01 17:32:41.962 D: DEBUG: count_usable_descriptors: 1389 usable, 96 present (microdesc exit policies and flags).
2022-02-01 17:32:41.963 D: DEBUG: compute_frac_paths_available: exits: 96 present, 1389 usable
2022-02-01 17:32:41.963 D: DEBUG: compute_weighted_bandwidths: Generated weighted bandwidths for rule weight as guard based on weights Wg=0.600700 Wm=0.600700 We=0.000000 Wd=0.000000 with total bw 33039303135.900002
2022-02-01 17:32:41.963 D: DEBUG: compute_weighted_bandwidths: Generated weighted bandwidths for rule weight as middle node based on weights Wg=0.399300 Wm=1.000000 We=0.000000 Wd=0.000000 with total bw 33038899864.099998
2022-02-01 17:32:41.963 D: DEBUG: compute_weighted_bandwidths: Generated weighted bandwidths for rule weight as exit based on weights Wg=1.000000 Wm=1.000000 We=1.000000 Wd=1.000000 with total bw 27523872000.000000
2022-02-01 17:32:41.963 D: DEBUG: compute_frac_paths_available: f_guard: 0.08, f_mid: 0.09, f_exit: 0.07
2022-02-01 17:32:41.963 D: INFO: I learned some more directory information, but not enough to build a circuit: We need more microdescriptors: we have 500/6845, and can only build 0% of likely paths. (We have 7% of guards bw, 8% of midpoint bw, and 7% of exit bw = 0% of path bw.)
2022-02-01 17:32:41.963 D: DEBUG: conn_close_if_marked: Cleaning up connection (fd -1).
2022-02-01 17:32:41.963 D: DEBUG: connection_remove: removing socket -1 (type Directory), n_conns now 37
2022-02-01 17:32:41.963 D: INFO: connection_free_minimal: Freeing linked Directory connection [client finished] with 0 bytes on inbuf, 0 on outbuf.
2022-02-01 17:32:41.963 D: DEBUG: conn_read_callback: socket -1 wants to read.
2022-02-01 17:32:41.963 D: DEBUG: connection_dir_process_inbuf: Got data, not eof. Leaving on inbuf.
2022-02-01 17:32:41.963 D: DEBUG: scheduler_evt_callback: Scheduler event callback called
2022-02-01 17:32:41.963 D: DEBUG: update_socket_info: chan=5 updated socket info, limit: 34752, cwnd: 0, unacked: 0, notsent: 0, mss: 0
2022-02-01 17:32:41.963 D: DEBUG: kist_scheduler_run: Running the scheduler. 1 channels pending
2022-02-01 17:32:41.963 D: DEBUG: outbuf_table_add: scheduler init outbuf info for chan=5
2022-02-01 17:32:41.964 D: DEBUG: channel_write_packed_cell: Writing 0xb40000725ab49b40 to channel 0xb40000725ab36a00 with global ID 5
2022-02-01 17:32:41.964 D: DEBUG: update_socket_written: chan=5 wrote 543 bytes, old was 0
2022-02-01 17:32:41.964 D: DEBUG: scheduler_set_channel_state: chan 5 changed from scheduler state PENDING to PENDING
2022-02-01 17:32:41.964 D: DEBUG: channel_write_packed_cell: Writing 0xb40000725ab45390 to channel 0xb40000725ab36a00 with global ID 5
2022-02-01 17:32:41.964 D: DEBUG: update_socket_written: chan=5 wrote 543 bytes, old was 543
2022-02-01 17:32:41.964 D: DEBUG: scheduler_set_channel_state: chan 5 changed from scheduler state PENDING to PENDING
2022-02-01 17:32:41.964 D: DEBUG: channel_write_packed_cell: Writing 0xb40000725ab46d00 to channel 0xb40000725ab36a00 with global ID 5
2022-02-01 17:32:41.964 D: DEBUG: channel_flush_from_first_active_circuit: Made a circuit inactive.
2022-02-01 17:32:41.964 D: DEBUG: update_socket_written: chan=5 wrote 543 bytes, old was 1086
2022-02-01 17:32:41.964 D: DEBUG: scheduler_set_channel_state: chan 5 changed from scheduler state PENDING to WAITING_FOR_CELLS
2022-02-01 17:32:41.964 D: DEBUG: channel_write_to_kernel: Writing 1542 bytes to kernel for chan 5
2022-02-01 17:32:41.964 D: DEBUG: flush_chunk_tls: flushed 1542 bytes, 0 remain.
2022-02-01 17:32:41.964 D: DEBUG: connection_handle_write_impl: After TLS write of 1542: 0 read, 1571 written
2022-02-01 17:32:41.964 D: DEBUG: free_outbuf_info_by_ent: Freeing outbuf table entry from chan=5
2022-02-01 17:32:41.965 D: DEBUG: kist_scheduler_run: len pending=0, len to_readd=-1
2022-02-01 17:32:41.965 D: DEBUG: conn_read_callback: socket 75 wants to read.
2022-02-01 17:32:42.257 D: DEBUG: connection_or_process_cells_from_inbuf: 75: starting, inbuf_datalen 2442 (0 pending in tls object).
2022-02-01 17:32:42.257 D: DEBUG: channel_process_cell: Processing incoming cell_t 0x7101bb2658 for channel 0xb40000725ab36a00 (global ID 5)
2022-02-01 17:32:42.257 D: DEBUG: circuit_get_by_circid_channel_impl: circuit_get_by_circid_channel_impl() returning circuit 0xb40000725ab377e0 for circ_id 2917690044, channel ID 5 (0xb40000725ab36a00)
2022-02-01 17:32:42.257 D: DEBUG: relay_lookup_conn: found conn for stream 171.
2022-02-01 17:32:42.257 D: DEBUG: circuit_receive_relay_cell: Sending to origin.
2022-02-01 17:32:42.257 D: DEBUG: connection_edge_process_relay_cell: Now seen 2110 relay cells here (command 2, stream 171).
2022-02-01 17:32:42.257 D: DEBUG: sendme_circuit_data_received: Circuit deliver_window now 900.
2022-02-01 17:32:42.258 D: DEBUG: sendme_circuit_consider_sending: Queuing circuit sendme.
2022-02-01 17:32:42.258 D: DEBUG: send_circuit_level_sendme: Emitting SENDME version 1 cell.
2022-02-01 17:32:42.258 D: DEBUG: relay_send_command_from_edge_: delivering 5 cell forward.
2022-02-01 17:32:42.258 D: DEBUG: relay_encrypt_cell_outbound: encrypting a layer of the relay cell.
2022-02-01 17:32:42.258 D: DEBUG: connection_or_process_cells_from_inbuf: 75: starting, inbuf_datalen 1928 (0 pending in tls object).
2022-02-01 17:32:42.258 D: DEBUG: channel_process_cell: Processing incoming cell_t 0x7101bb2658 for channel 0xb40000725ab36a00 (global ID 5)
2022-02-01 17:32:42.258 D: DEBUG: circuit_get_by_circid_channel_impl: circuit_get_by_circid_channel_impl() returning circuit 0xb40000725ab377e0 for circ_id 2917690044, channel ID 5 (0xb40000725ab36a00)
2022-02-01 17:32:42.258 D: DEBUG: relay_lookup_conn: found conn for stream 171.
2022-02-01 17:32:42.258 D: DEBUG: circuit_receive_relay_cell: Sending to origin.
2022-02-01 17:32:42.258 D: DEBUG: connection_edge_process_relay_cell: Now seen 2111 relay cells here (command 2, stream 171).
2022-02-01 17:32:42.258 D: DEBUG: sendme_circuit_data_received: Circuit deliver_window now 999.
2022-02-01 17:32:42.258 D: DEBUG: connection_or_process_cells_from_inbuf: 75: starting, inbuf_datalen 1414 (0 pending in tls object).
2022-02-01 17:32:42.258 D: DEBUG: channel_process_cell: Processing incoming cell_t 0x7101bb2658 for channel 0xb40000725ab36a00 (global ID 5)
2022-02-01 17:32:42.259 D: DEBUG: circuit_get_by_circid_channel_impl: circuit_get_by_circid_channel_impl() returning circuit 0xb40000725ab377e0 for circ_id 2917690044, channel ID 5 (0xb40000725ab36a00)
2022-02-01 17:32:42.259 D: DEBUG: relay_lookup_conn: found conn for stream 171.
2022-02-01 17:32:42.259 D: DEBUG: circuit_receive_relay_cell: Sending to origin.
2022-02-01 17:32:42.259 D: DEBUG: connection_edge_process_relay_cell: Now seen 2112 relay cells here (command 2, stream 171).
2022-02-01 17:32:42.259 D: DEBUG: sendme_circuit_data_received: Circuit deliver_window now 998.
2022-02-01 17:32:42.259 D: DEBUG: connection_or_process_cells_from_inbuf: 75: starting, inbuf_datalen 900 (0 pending in tls object).
2022-02-01 17:32:42.259 D: DEBUG: channel_process_cell: Processing incoming cell_t 0x7101bb2658 for channel 0xb40000725ab36a00 (global ID 5)
2022-02-01 17:32:42.259 D: DEBUG: circuit_get_by_circid_channel_impl: circuit_get_by_circid_channel_impl() returning circuit 0xb40000725ab377e0 for circ_id 2917690044, channel ID 5 (0xb40000725ab36a00)
2022-02-01 17:32:42.259 D: DEBUG: relay_lookup_conn: found conn for stream 171.
2022-02-01 17:32:42.259 D: DEBUG: circuit_receive_relay_cell: Sending to origin.
2022-02-01 17:32:42.259 D: DEBUG: connection_edge_process_relay_cell: Now seen 2113 relay cells here (command 2, stream 171).
2022-02-01 17:32:42.259 D: DEBUG: sendme_circuit_data_received: Circuit deliver_window now 997.
2022-02-01 17:32:42.259 D: DEBUG: connection_or_process_cells_from_inbuf: 75: starting, inbuf_datalen 386 (0 pending in tls object).
2022-02-01 17:32:42.259 D: DEBUG: scheduler_evt_callback: Scheduler event callback called
2022-02-01 17:32:42.260 D: DEBUG: update_socket_info: chan=5 updated socket info, limit: 34752, cwnd: 0, unacked: 0, notsent: 0, mss: 0
2022-02-01 17:32:42.260 D: DEBUG: kist_scheduler_run: Running the scheduler. 1 channels pending
2022-02-01 17:32:42.260 D: DEBUG: outbuf_table_add: scheduler init outbuf info for chan=5
2022-02-01 17:32:42.260 D: DEBUG: channel_write_packed_cell: Writing 0xb40000725ab49b40 to channel 0xb40000725ab36a00 with global ID 5
2022-02-01 17:32:42.260 D: DEBUG: update_socket_written: chan=5 wrote 543 bytes, old was 0
2022-02-01 17:32:42.260 D: DEBUG: scheduler_set_channel_state: chan 5 changed from scheduler state PENDING to PENDING
2022-02-01 17:32:42.260 D: DEBUG: channel_write_packed_cell: Writing 0xb40000725ab46d00 to channel 0xb40000725ab36a00 with global ID 5
2022-02-01 17:32:42.260 D: DEBUG: update_socket_written: chan=5 wrote 543 bytes, old was 543
2022-02-01 17:32:42.260 D: DEBUG: scheduler_set_channel_state: chan 5 changed from scheduler state PENDING to PENDING
2022-02-01 17:32:42.260 D: DEBUG: channel_write_packed_cell: Writing 0xb40000725ab45390 to channel 0xb40000725ab36a00 with global ID 5
2022-02-01 17:32:42.260 D: DEBUG: update_socket_written: chan=5 wrote 543 bytes, old was 1086
2022-02-01 17:32:42.261 D: DEBUG: scheduler_set_channel_state: chan 5 changed from scheduler state PENDING to PENDING
2022-02-01 17:32:42.261 D: DEBUG: channel_write_packed_cell: Writing 0xb40000725ab2b350 to channel 0xb40000725ab36a00 with global ID 5
2022-02-01 17:32:42.261 D: DEBUG: update_socket_written: chan=5 wrote 543 bytes, old was 1629
2022-02-01 17:32:42.261 D: DEBUG: scheduler_set_channel_state: chan 5 changed from scheduler state PENDING to PENDING
2022-02-01 17:32:42.261 D: DEBUG: channel_write_packed_cell: Writing 0xb40000725ab290a0 to channel 0xb40000725ab36a00 with global ID 5
2022-02-01 17:32:42.261 D: DEBUG: channel_flush_from_first_active_circuit: Made a circuit inactive.
2022-02-01 17:32:42.261 D: DEBUG: update_socket_written: chan=5 wrote 543 bytes, old was 2172
2022-02-01 17:32:42.261 D: DEBUG: scheduler_set_channel_state: chan 5 changed from scheduler state PENDING to WAITING_FOR_CELLS
2022-02-01 17:32:42.261 D: DEBUG: channel_write_to_kernel: Writing 2570 bytes to kernel for chan 5
2022-02-01 17:32:42.261 D: DEBUG: flush_chunk_tls: flushed 2570 bytes, 0 remain.
2022-02-01 17:32:42.261 D: DEBUG: connection_handle_write_impl: After TLS write of 2570: 0 read, 2599 written
2022-02-01 17:32:42.261 D: DEBUG: free_outbuf_info_by_ent: Freeing outbuf table entry from chan=5
2022-02-01 17:32:42.261 D: DEBUG: kist_scheduler_run: len pending=0, len to_readd=-1
2022-02-01 17:32:42.261 D: DEBUG: conn_read_callback: socket -1 wants to read.
2022-02-01 17:32:42.262 D: DEBUG: connection_dir_process_inbuf: Got data, not eof. Leaving on inbuf.
2022-02-01 17:32:42.262 D: DEBUG: conn_read_callback: socket -1 wants to read.
2022-02-01 17:32:42.262 D: DEBUG: connection_dir_process_inbuf: Got data, not eof. Leaving on inbuf.
2022-02-01 17:32:42.262 D: DEBUG: conn_read_callback: socket 75 wants to read.
2022-02-01 17:32:42.262 D: DEBUG: connection_buf_read_from_socket: 75: starting, inbuf_datalen 386 (0 pending in tls object). at_most 14858.
2022-02-01 17:32:42.262 D: DEBUG: tor_tls_read: read returned r=-1, err=-2
2022-02-01 17:32:42.262 D: DEBUG: connection_buf_read_from_socket: After TLS read of 4176: 5189 read, 0 written
2022-02-01 17:32:42.262 D: DEBUG: connection_or_process_cells_from_inbuf: 75: starting, inbuf_datalen 4562 (0 pending in tls object).
2022-02-01 17:32:42.262 D: DEBUG: channel_process_cell: Processing incoming cell_t 0x7101bb2658 for channel 0xb40000725ab36a00 (global ID 5)
2022-02-01 17:32:42.262 D: DEBUG: circuit_get_by_circid_channel_impl: circuit_get_by_circid_channel_impl() returning circuit 0xb40000725ab377e0 for circ_id 2917690044, channel ID 5 (0xb40000725ab36a00)
2022-02-01 17:32:42.262 D: DEBUG: relay_lookup_conn: found conn for stream 171.
2022-02-01 17:32:42.262 D: DEBUG: circuit_receive_relay_cell: Sending to origin.
2022-02-01 17:32:42.372 D: DEBUG: channel_process_cell: Processing incoming cell_t 0x7101bb2658 for channel 0xb40000725ab36a00 (global ID 5)
2022-02-01 17:32:42.372 D: DEBUG: circuit_get_by_circid_channel_impl: circuit_get_by_circid_channel_impl() returning circuit 0xb40000725ab377e0 for circ_id 2917690044, channel ID 5 (0xb40000725ab36a00)
2022-02-01 17:32:42.372 D: DEBUG: relay_lookup_conn: found conn for stream 171.
2022-02-01 17:32:42.372 D: DEBUG: circuit_receive_relay_cell: Sending to origin.
2022-02-01 17:32:42.373 D: DEBUG: connection_edge_process_relay_cell: Now seen 2281 relay cells here (command 2, stream 171).
2022-02-01 17:32:42.373 D: DEBUG: sendme_circuit_data_received: Circuit deliver_window now 929.
2022-02-01 17:32:42.373 D: DEBUG: connection_or_process_cells_from_inbuf: 75: starting, inbuf_datalen 5140 (0 pending in tls object).
2022-02-01 17:32:42.373 D: DEBUG: channel_process_cell: Processing incoming cell_t 0x7101bb2658 for channel 0xb40000725ab36a00 (global ID 5)
2022-02-01 17:32:42.373 D: DEBUG: circuit_get_by_circid_channel_impl: circuit_get_by_circid_channel_impl() returning circuit 0xb40000725ab377e0 for circ_id 2917690044, channel ID 5 (0xb40000725ab36a00)
2022-02-01 17:32:42.373 D: DEBUG: relay_lookup_conn: found conn for stream 171.
2022-02-01 17:32:42.373 D: DEBUG: circuit_receive_relay_cell: Sending to origin.
2022-02-01 17:32:42.373 D: DEBUG: connection_edge_process_relay_cell: Now seen 2282 relay cells here (command 2, stream 171).
2022-02-01 17:32:42.373 D: DEBUG: sendme_circuit_data_received: Circuit deliver_window now 928.
2022-02-01 17:32:42.373 D: DEBUG: connection_or_process_cells_from_inbuf: 75: starting, inbuf_datalen 4626 (0 pending in tls object).
2022-02-01 17:32:42.373 D: DEBUG: channel_process_cell: Processing incoming cell_t 0x7101bb2658 for channel 0xb40000725ab36a00 (global ID 5)
2022-02-01 17:32:42.373 D: DEBUG: circuit_get_by_circid_channel_impl: circuit_get_by_circid_channel_impl() returning circuit 0xb40000725ab377e0 for circ_id 2917690044, channel ID 5 (0xb40000725ab36a00)
2022-02-01 17:32:42.374 D: DEBUG: relay_lookup_conn: found conn for stream 171.
2022-02-01 17:32:42.374 D: DEBUG: circuit_receive_relay_cell: Sending to origin.
2022-02-01 17:32:42.374 D: DEBUG: connection_edge_process_relay_cell: Now seen 2283 relay cells here (command 2, stream 171).
2022-02-01 17:32:42.374 D: DEBUG: sendme_circuit_data_received: Circuit deliver_window now 927.
2022-02-01 17:32:42.374 D: DEBUG: connection_or_process_cells_from_inbuf: 75: starting, inbuf_datalen 4112 (0 pending in tls object).
2022-02-01 17:32:42.374 D: DEBUG: channel_process_cell: Processing incoming cell_t 0x7101bb2658 for channel 0xb40000725ab36a00 (global ID 5)
2022-02-01 17:32:42.374 D: DEBUG: circuit_get_by_circid_channel_impl: circuit_get_by_circid_channel_impl() returning circuit 0xb40000725ab377e0 for circ_id 2917690044, channel ID 5 (0xb40000725ab36a00)
2022-02-01 17:32:42.374 D: DEBUG: relay_lookup_conn: found conn for stream 171.
2022-02-01 17:32:42.374 D: DEBUG: circuit_receive_relay_cell: Sending to origin.
2022-02-01 17:32:42.374 D: DEBUG: connection_edge_process_relay_cell: Now seen 2284 relay cells here (command 2, stream 171).
2022-02-01 17:32:42.374 D: DEBUG: sendme_circuit_data_received: Circuit deliver_window now 926.
2022-02-01 17:32:42.374 D: DEBUG: connection_or_process_cells_from_inbuf: 75: starting, inbuf_datalen 3598 (0 pending in tls object).
2022-02-01 17:32:42.374 D: DEBUG: channel_process_cell: Processing incoming cell_t 0x7101bb2658 for channel 0xb40000725ab36a00 (global ID 5)
2022-02-01 17:32:42.374 D: DEBUG: circuit_get_by_circid_channel_impl: circuit_get_by_circid_channel_impl() returning circuit 0xb40000725ab377e0 for circ_id 2917690044, channel ID 5 (0xb40000725ab36a00)
2022-02-01 17:32:42.374 D: DEBUG: relay_lookup_conn: found conn for stream 171.
2022-02-01 17:32:42.375 D: DEBUG: circuit_receive_relay_cell: Sending to origin.
2022-02-01 17:32:42.375 D: DEBUG: connection_edge_process_relay_cell: Now seen 2285 relay cells here (command 2, stream 171).
2022-02-01 17:32:42.375 D: DEBUG: sendme_circuit_data_received: Circuit deliver_window now 925.
2022-02-01 17:32:42.375 D: DEBUG: connection_or_process_cells_from_inbuf: 75: starting, inbuf_datalen 3084 (0 pending in tls object).
2022-02-01 17:32:42.375 D: DEBUG: channel_process_cell: Processing incoming cell_t 0x7101bb2658 for channel 0xb40000725ab36a00 (global ID 5)
2022-02-01 17:32:42.375 D: DEBUG: circuit_get_by_circid_channel_impl: circuit_get_by_circid_channel_impl() returning circuit 0xb40000725ab377e0 for circ_id 2917690044, channel ID 5 (0xb40000725ab36a00)
2022-02-01 17:32:42.375 D: DEBUG: relay_lookup_conn: found conn for stream 171.
2022-02-01 17:32:42.375 D: DEBUG: circuit_receive_relay_cell: Sending to origin.
2022-02-01 17:32:42.375 D: DEBUG: connection_edge_process_relay_cell: Now seen 2286 relay cells here (command 2, stream 171).
2022-02-01 17:32:42.375 D: DEBUG: sendme_circuit_data_received: Circuit deliver_window now 924.
2022-02-01 17:32:42.375 D: DEBUG: connection_or_process_cells_from_inbuf: 75: starting, inbuf_datalen 2570 (0 pending in tls object).
2022-02-01 17:32:42.375 D: DEBUG: channel_process_cell: Processing incoming cell_t 0x7101bb2658 for channel 0xb40000725ab36a00 (global ID 5)
2022-02-01 17:32:42.375 D: DEBUG: circuit_get_by_circid_channel_impl: circuit_get_by_circid_channel_impl() returning circuit 0xb40000725ab377e0 for circ_id 2917690044, channel ID 5 (0xb40000725ab36a00)
2022-02-01 17:32:42.376 D: DEBUG: relay_lookup_conn: found conn for stream 171.
2022-02-01 17:32:42.376 D: DEBUG: circuit_receive_relay_cell: Sending to origin.
2022-02-01 17:32:42.376 D: DEBUG: connection_edge_process_relay_cell: Now seen 2287 relay cells here (command 2, stream 171).
2022-02-01 17:32:42.376 D: DEBUG: sendme_circuit_data_received: Circuit deliver_window now 923.
2022-02-01 17:32:42.376 D: DEBUG: connection_or_process_cells_from_inbuf: 75: starting, inbuf_datalen 2056 (0 pending in tls object).
2022-02-01 17:32:42.376 D: DEBUG: channel_process_cell: Processing incoming cell_t 0x7101bb2658 for channel 0xb40000725ab36a00 (global ID 5)
2022-02-01 17:32:42.376 D: DEBUG: circuit_get_by_circid_channel_impl: circuit_get_by_circid_channel_impl() returning circuit 0xb40000725ab377e0 for circ_id 2917690044, channel ID 5 (0xb40000725ab36a00)
2022-02-01 17:32:42.376 D: DEBUG: relay_lookup_conn: found conn for stream 171.
2022-02-01 17:32:42.376 D: DEBUG: circuit_receive_relay_cell: Sending to origin.
2022-02-01 17:32:42.376 D: DEBUG: connection_edge_process_relay_cell: Now seen 2288 relay cells here (command 2, stream 171).
2022-02-01 17:32:42.376 D: DEBUG: sendme_circuit_data_received: Circuit deliver_window now 922.
2022-02-01 17:32:42.376 D: DEBUG: connection_or_process_cells_from_inbuf: 75: starting, inbuf_datalen 1542 (0 pending in tls object).
2022-02-01 17:32:42.376 D: DEBUG: channel_process_cell: Processing incoming cell_t 0x7101bb2658 for channel 0xb40000725ab36a00 (global ID 5)
2022-02-01 17:32:42.377 D: DEBUG: circuit_get_by_circid_channel_impl: circuit_get_by_circid_channel_impl() returning circuit 0xb40000725ab377e0 for circ_id 2917690044, channel ID 5 (0xb40000725ab36a00)
2022-02-01 17:32:42.377 D: DEBUG: relay_lookup_conn: found conn for stream 171.
2022-02-01 17:32:42.377 D: DEBUG: circuit_receive_relay_cell: Sending to origin.
2022-02-01 17:32:42.377 D: DEBUG: connection_edge_process_relay_cell: Now seen 2289 relay cells here (command 2, stream 171).
2022-02-01 17:32:42.377 D: DEBUG: sendme_circuit_data_received: Circuit deliver_window now 921.
2022-02-01 17:32:42.377 D: DEBUG: connection_or_process_cells_from_inbuf: 75: starting, inbuf_datalen 1028 (0 pending in tls object).

Letting Tor sit there, does not produce any more log messages. The process is still shown as running.

Possible fixes

???

Edited by grote
To upload designs, you'll need to enable LFS and have an admin enable hashed storage. More information