Opened 13 years ago

Last modified 7 years ago

#222 closed defect (Fixed)

an abort() in delete_log

Reported by: weasel Owned by: nickm
Priority: Low Milestone: post 0.1.2.x
Component: Core Tor/Tor Version: 0.1.1.10-alpha
Severity: Keywords:
Cc: weasel Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

One of my short lived Tors (start with fresh data directory, run for a minute, sent TERM):

After sending a SIGNAL TERM to my tor, it died with an abort() in delete_log():

(gdb) bt
#0 0x556f583b in raise () from /lib/tls/libc.so.6
#1 0x556f6fa2 in abort () from /lib/tls/libc.so.6
#2 0x080ac462 in delete_log (victim=0x80fd2c0) at log.c:339
#3 0x080ac2af in logv (severity=6, domain=65536, funcname=0x80d2301 "dnsworker_main",

format=0x80d22a0 "DNS worker exiting because Tor process closed connection (either pruned idle dnsworker or died).", ap=0x56825960 "")
at log.c:227

#4 0x080ac332 in _log_fn (severity=6, domain=65536, fn=0x80d2301 "dnsworker_main",

format=0x80d22a0 "DNS worker exiting because Tor process closed connection (either pruned idle dnsworker or died).") at log.c:251

#5 0x080878ad in dnsworker_main (data=0x0) at dns.c:815
#6 0x080b181e in tor_pthread_helper_fn (_data=0x0) at compat.c:819
#7 0x556b7b63 in start_thread () from /lib/tls/libpthread.so.0
#8 0x557a518a in clone () from /lib/tls/libc.so.6

[Automatically added by flyspray2trac: Operating System: All]

Child Tickets

Change History (8)

comment:1 Changed 13 years ago by weasel

info level log:
Dec 19 12:33:02.352 [info] connection_ap_make_bridge(): Making AP bridge to 127.0.0.1:19031 ...
Dec 19 12:33:02.353 [info] exit circ (length 3): tor13(open) tor23(open) tor5(open)
Dec 19 12:33:02.353 [info] connection_ap_handshake_send_begin(): Address/port sent, ap socket 35, n_circ_id 16879
Dec 19 12:33:02.353 [info] connection_ap_make_bridge(): ... AP bridge created and connected.
Dec 19 12:33:02.353 [info] connection_ap_make_bridge(): Making AP bridge to 127.0.0.2:19032 ...
Dec 19 12:33:02.353 [info] exit circ (length 3): tor13(open) tor23(open) tor5(open)
Dec 19 12:33:02.353 [info] connection_ap_handshake_send_begin(): Address/port sent, ap socket 37, n_circ_id 16879
Dec 19 12:33:02.353 [info] connection_ap_make_bridge(): ... AP bridge created and connected.
Dec 19 12:33:02.353 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for connect' state. Leaving it on buffer.
Dec 19 12:33:02.353 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for connect' state. Leaving it on buffer.
Dec 19 12:33:02.353 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for connect' state. Leaving it on buffer.
Dec 19 12:33:02.353 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for connect' state. Leaving it on buffer.
Dec 19 12:33:02.355 [info] connection_edge_process_relay_cell_not_open(): 'connected' received after 0 seconds.
Dec 19 12:33:02.355 [info] exit circ (length 3): tor13(open) tor23(open) tor5(open)
Dec 19 12:33:02.355 [info] connection_edge_process_relay_cell_not_open(): 'connected' received after 0 seconds.
Dec 19 12:33:02.355 [info] exit circ (length 3): tor13(open) tor23(open) tor5(open)
Dec 19 12:33:02.357 [info] connection_edge_process_relay_cell(): 37: end cell (closed normally) for stream 50334. Removing stream.
Dec 19 12:33:02.357 [info] connection_edge_process_relay_cell(): 35: end cell (closed normally) for stream 50333. Removing stream.
Dec 19 12:33:02.357 [info] connection_dir_client_reached_eof(): Uploading rendezvous descriptor: finished with status 200 ("Service descriptor stored")
Dec 19 12:33:02.357 [info] connection_dir_client_reached_eof(): Uploading rendezvous descriptor: finished with status 200 ("Service descriptor stored")
Dec 19 12:33:12.207 [info] rend_mid_establish_intro(): Received an ESTABLISH_INTRO request on circuit 23324
Dec 19 12:33:12.207 [info] rend_mid_establish_intro(): Established introduction point on circuit 23324 for service ixio3yn227swus2q
Dec 19 12:33:18.426 [info] update_router_descriptor_downloads(): There are not many downloadable routerdescs, but we've been waiting long enough (60 seconds). Downloading.
Dec 19 12:33:18.426 [info] update_router_descriptor_downloads(): Launching 1 request for 1 router, 128 at a time
Dec 19 12:33:18.427 [info] connection_dir_client_reached_eof(): Received server info (size 1102) from server '127.0.0.1:19031'
Dec 19 12:33:18.438 [info] connection_dir_client_reached_eof(): Received 1/1 routers requested from 127.0.0.1:19031
Dec 19 12:33:26.190 [info] rend_mid_establish_intro(): Received an ESTABLISH_INTRO request on circuit 5875
Dec 19 12:33:26.190 [info] rend_mid_establish_intro(): Established introduction point on circuit 5875 for service i4t5zhvejqu475oy
Dec 19 12:33:28.244 [info] circuit_extend(): Next router (127.0.0.30:19030) not connected. Connecting.
Dec 19 12:33:30.149 [info] connection_control_process_inbuf_v0(): Detected v1 control protocol on connection (fd 37)
Dec 19 12:33:30.149 [info] handle_control_authenticate(): Authenticated control connection (37)
Dec 19 12:33:30.149 [err] signal_callback(): Catching signal TERM, exiting cleanly.
Dec 19 12:33:30.206 [info] cpuworker_main(): CPU worker exiting because Tor process closed connection (either rotated keys or died).
Dec 19 12:33:34.263 [notice] Tor 0.1.1.10-alpha-cvs opening log file.
Dec 19 12:33:34.263 [info] or_state_load(): Initialized state
Dec 19 12:33:34.263 [info] or_state_save(): Saved state to "data/state"
Dec 19 12:33:34.263 [info] rend_service_load_keys(): Loading hidden-service keys from "hid1"
Dec 19 12:33:34.263 [info] check_private_dir(): Creating directory hid1
Dec 19 12:33:34.263 [info] init_key_from_file(): No key found in "hid1/private_key"; generating fresh key.
Dec 19 12:33:34.331 [info] init_key_from_file(): Generated key seems valid
Dec 19 12:33:34.331 [info] rend_service_load_keys(): Loading hidden-service keys from "hid2"
Dec 19 12:33:34.346 [info] crypto_global_init(): Initializing OpenSSL engine support.
Dec 19 12:33:34.348 [info] Using default implementation for RSA
Dec 19 12:33:34.348 [info] Using default implementation for DH
Dec 19 12:33:34.348 [info] Using default implementation for RAND
Dec 19 12:33:34.348 [info] Using default implementation for SHA1
Dec 19 12:33:34.348 [info] Using default implementation for 3DES
Dec 19 12:33:34.348 [info] Using default implementation for AES
Dec 19 12:33:34.348 [info] crypto_seed_rng(): Seeding RNG from "/dev/urandom"
Dec 19 12:33:34.348 [info] check_private_dir(): Creating directory data/keys
Dec 19 12:33:34.348 [info] init_keys(): Reading/making identity key "data/keys/secret_id_key"...
Dec 19 12:33:34.348 [info] init_key_from_file(): No key found in "data/keys/secret_id_key"; generating fresh key.
Dec 19 12:33:34.581 [info] init_key_from_file(): Generated key seems valid
Dec 19 12:33:34.581 [info] init_keys(): Reading/making onion key "data/keys/secret_onion_key"...
Dec 19 12:33:34.581 [info] init_key_from_file(): No key found in "data/keys/secret_onion_key"; generating fresh key.
Dec 19 12:33:34.719 [info] init_key_from_file(): Generated key seems valid
Dec 19 12:33:34.824 [info] config_expand_exit_policy_aliases(): Expanded 'reject private:*,reject *:25,reject *:119,reject *:135-139,reject *:445,reject *:465,reject *:587,reject *:1214,reject *:4661-4666,reject *:6346-6429,reject *:6699,reject *:6881-6999,accept *:*' to 'reject 0.0.0.0/8:*,reject 169.254.0.0/16:*,reject 127.0.0.0/8:*,reject 192.168.0.0/16:*,reject 10.0.0.0/8:*,reject 172.16.0.0/12:*,reject *:25,reject *:119,reject *:135-139,reject *:445,reject *:465,reject *:587,reject *:1214,reject *:4661-4666,reject *:6346-6429,reject *:6699,reject *:6881-6999,accept *:*'
Dec 19 12:33:34.827 [info] init_keys(): Dumping descriptor to "data/router.desc"...
Dec 19 12:33:34.828 [info] init_keys(): Dumping fingerprint to "data/fingerprint"...
Dec 19 12:33:34.828 [info] read_file_to_str(): Could not stat "data/cached-routers".
Dec 19 12:33:34.828 [info] read_file_to_str(): Could not stat "data/cached-routers.new".
Dec 19 12:33:34.828 [notice] I learned some more directory information, but not enough to build a circuit.
Dec 19 12:33:34.828 [notice] update_router_descriptor_downloads(): Launching request for all routers
Dec 19 12:33:36.299 [info] connection_read_to_buf(): tls error. breaking (nickname $8A00895D073EE39578BF1701EE156AC8D1BC8981, address 127.0.0.43).
Dec 19 12:33:36.599 [info] connection_dir_client_reached_eof(): eof (status 200) after uploading server descriptor: finished.
Dec 19 12:33:36.611 [info] connection_dir_client_reached_eof(): Received running-routers list (size 315451)
Dec 19 12:33:36.713 [info] connection_dir_client_reached_eof(): Received networkstatus objects (size 1775078) from server '127.0.0.1:19031'
Dec 19 12:33:36.783 [info] router_set_networkstatus(): Setting networkstatus downloaded from directory server at 127.0.0.1:19031 (published 2005-12-19 11:32:57)
Dec 19 12:33:36.785 [info] networkstatus_list_update_recent(): Networkstatus from directory server at 127.0.0.1:19031 (published 2005-12-19 11:32:57) is now "recent"
Dec 19 12:33:36.947 [info] router_set_networkstatus(): Setting networkstatus downloaded from directory server at 127.0.0.2:19032 (published 2005-12-19 11:31:33)
Dec 19 12:33:36.949 [info] networkstatus_list_update_recent(): Networkstatus from directory server at 127.0.0.2:19032 (published 2005-12-19 11:31:33) is now "recent"
Dec 19 12:33:37.046 [info] routerstatus_list_update_from_networkstatus(): Rebuilding router status list.
Dec 19 12:33:37.050 [info] routers_update_all_from_networkstatus(): 0/2 recent directories think my version is ok.
Dec 19 12:33:37.051 [notice] I learned some more directory information, but not enough to build a circuit.
Dec 19 12:33:37.051 [info] connection_dir_client_reached_eof(): eof (status 200) after uploading server descriptor: finished.
Dec 19 12:33:37.203 [info] connection_dir_client_reached_eof(): Received server info (size 7089072) from server '127.0.0.2:19032'
Dec 19 12:33:49.166 [notice] We now have enough directory information to build circuits.
Dec 19 12:33:49.222 [info] rend_services_introduce(): Picked router tor18 as an intro point for upxlw4s7cpagkusq.
Dec 19 12:33:49.222 [info] rend_services_introduce(): Picked router tor15 as an intro point for upxlw4s7cpagkusq.
Dec 19 12:33:49.222 [info] rend_services_introduce(): Picked router tor25 as an intro point for upxlw4s7cpagkusq.
Dec 19 12:33:49.222 [info] rend_service_launch_establish_intro(): Launching circuit to introduction point $5CFB4ED85FA9AC54E342172D9FD8DB571FBDF02A for service upxlw4s7cpagkusq
Dec 19 12:33:49.222 [info] onion_pick_cpath_exit(): Using requested exit node 'tor18'
Dec 19 12:33:49.224 [info] rend_service_launch_establish_intro(): Launching circuit to introduction point $ADCA0334105CEBA222E1D78B348F1ADCA9C065E6 for service upxlw4s7cpagkusq
Dec 19 12:33:49.224 [info] onion_pick_cpath_exit(): Using requested exit node 'tor15'
Dec 19 12:33:49.226 [info] rend_service_launch_establish_intro(): Launching circuit to introduction point $44A750378A4D0238843CF07B2137FAEE367A23FA for service upxlw4s7cpagkusq
Dec 19 12:33:49.226 [info] onion_pick_cpath_exit(): Using requested exit node 'tor25'
Dec 19 12:33:49.228 [info] rend_services_introduce(): Picked router tor5 as an intro point for pncas3abo2uirlci.
Dec 19 12:33:49.228 [info] rend_services_introduce(): Picked router tor12 as an intro point for pncas3abo2uirlci.
Dec 19 12:33:49.228 [info] rend_services_introduce(): Picked router tor28 as an intro point for pncas3abo2uirlci.
Dec 19 12:33:49.228 [info] rend_service_launch_establish_intro(): Launching circuit to introduction point $D3F05C619BAD600DDCD11FCE0C202B3B4E01431D for service pncas3abo2uirlci
Dec 19 12:33:49.228 [info] onion_pick_cpath_exit(): Using requested exit node 'tor5'
Dec 19 12:33:49.230 [info] rend_service_launch_establish_intro(): Launching circuit to introduction point $8A00895D073EE39578BF1701EE156AC8D1BC8981 for service pncas3abo2uirlci
Dec 19 12:33:49.230 [info] onion_pick_cpath_exit(): Using requested exit node 'tor12'
Dec 19 12:33:49.231 [info] rend_service_launch_establish_intro(): Launching circuit to introduction point $3B832D2A9C89078628161782D87E83DC96F7E14F for service pncas3abo2uirlci
Dec 19 12:33:49.231 [info] onion_pick_cpath_exit(): Using requested exit node 'tor28'
Dec 19 12:33:49.233 [info] circuit_predict_and_launch_new(): Have 0 clean circs (0 internal), need another exit circ.
Dec 19 12:33:49.234 [info] choose_good_exit_server_general(): Found 36 servers that might support 0/0 pending connections.
Dec 19 12:33:49.234 [info] choose_good_exit_server_general(): Chose exit server 'tor1'
Dec 19 12:33:49.263 [info] circuit_send_next_onion_skin(): First hop: finished sending CREATE cell to 'tor17'
Dec 19 12:33:49.265 [info] circuit_send_next_onion_skin(): First hop: finished sending CREATE cell to 'tor17'
Dec 19 12:33:49.278 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:49.278 [info] internal (high-uptime) circ (length 3, exit tor18): tor17(open) tor42(closed) tor18(closed)
Dec 19 12:33:49.356 [info] circuit_send_next_onion_skin(): First hop: finished sending CREATE cell to 'tor4'
Dec 19 12:33:49.360 [info] circuit_send_next_onion_skin(): First hop: finished sending CREATE cell to 'tor22'
Dec 19 12:33:49.363 [info] circuit_send_next_onion_skin(): First hop: finished sending CREATE cell to 'tor7'
Dec 19 12:33:49.366 [info] circuit_send_next_onion_skin(): First hop: finished sending CREATE cell to 'tor21'
Dec 19 12:33:49.368 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:49.368 [info] internal (high-uptime) circ (length 3, exit tor12): tor17(open) tor1(closed) tor12(closed)
Dec 19 12:33:49.379 [info] circuit_send_next_onion_skin(): First hop: finished sending CREATE cell to 'tor8'
Dec 19 12:33:49.388 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:49.388 [info] internal (high-uptime) circ (length 3, exit tor18): tor17(open) tor42(open) tor18(closed)
Dec 19 12:33:49.392 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:49.392 [info] internal (high-uptime) circ (length 3, exit tor28): tor4(open) tor19(closed) tor28(closed)
Dec 19 12:33:49.396 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:49.396 [info] internal (high-uptime) circ (length 3, exit tor25): tor7(open) tor18(closed) tor25(closed)
Dec 19 12:33:49.400 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:49.400 [info] internal (high-uptime) circ (length 3, exit tor12): tor17(open) tor1(open) tor12(closed)
Dec 19 12:33:49.410 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:49.410 [info] exit circ (length 3, exit tor1): tor8(open) tor15(closed) tor1(closed)
Dec 19 12:33:49.418 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:49.418 [info] internal (high-uptime) circ (length 3, exit tor15): tor21(open) tor3(closed) tor15(closed)
Dec 19 12:33:49.422 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:49.422 [info] internal (high-uptime) circ (length 3, exit tor5): tor22(open) tor9(closed) tor5(closed)
Dec 19 12:33:49.433 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:49.433 [info] internal (high-uptime) circ (length 3, exit tor18): tor17(open) tor42(open) tor18(open)
Dec 19 12:33:49.433 [info] circuit_send_next_onion_skin(): circuit built!
Dec 19 12:33:49.433 [notice] Tor has successfully opened a circuit. Looks like it's working.
Dec 19 12:33:49.433 [info] rend_service_intro_has_opened(): Established circuit 9785 as introduction point for service upxlw4s7cpagkusq
Dec 19 12:33:49.438 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:49.438 [info] internal (high-uptime) circ (length 3, exit tor25): tor7(open) tor18(open) tor25(closed)
Dec 19 12:33:49.443 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:49.443 [info] internal (high-uptime) circ (length 3, exit tor12): tor17(open) tor1(open) tor12(open)
Dec 19 12:33:49.443 [info] circuit_send_next_onion_skin(): circuit built!
Dec 19 12:33:49.443 [info] rend_service_intro_has_opened(): Established circuit 9786 as introduction point for service pncas3abo2uirlci
Dec 19 12:33:49.534 [info] connection_dir_client_reached_eof(): Received directory (size 7404565) from server '127.0.0.2:19032'
Dec 19 12:33:50.250 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:50.250 [info] exit circ (length 3, exit tor1): tor8(open) tor15(open) tor1(closed)
Dec 19 12:33:50.254 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:50.254 [info] internal (high-uptime) circ (length 3, exit tor15): tor21(open) tor3(open) tor15(closed)
Dec 19 12:33:50.259 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:50.259 [info] internal (high-uptime) circ (length 3, exit tor5): tor22(open) tor9(open) tor5(closed)
Dec 19 12:33:50.263 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:50.263 [info] internal (high-uptime) circ (length 3, exit tor28): tor4(open) tor19(open) tor28(closed)
Dec 19 12:33:50.265 [info] circuit_predict_and_launch_new(): Have 1 clean circs (0 internal), need another exit circ.
Dec 19 12:33:50.267 [info] choose_good_exit_server_general(): Found 36 servers that might support 0/0 pending connections.
Dec 19 12:33:50.267 [info] choose_good_exit_server_general(): Chose exit server 'tor15'
Dec 19 12:33:50.271 [info] circuit_send_next_onion_skin(): First hop: finished sending CREATE cell to 'tor21'
Dec 19 12:33:50.273 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:50.273 [info] internal (high-uptime) circ (length 3, exit tor25): tor7(open) tor18(open) tor25(open)
Dec 19 12:33:50.273 [info] circuit_send_next_onion_skin(): circuit built!
Dec 19 12:33:50.273 [info] rend_service_intro_has_opened(): Established circuit 8716 as introduction point for service upxlw4s7cpagkusq
Dec 19 12:33:50.285 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:50.285 [info] internal (high-uptime) circ (length 3, exit tor28): tor4(open) tor19(open) tor28(open)
Dec 19 12:33:50.285 [info] circuit_send_next_onion_skin(): circuit built!
Dec 19 12:33:50.285 [info] rend_service_intro_has_opened(): Established circuit 24475 as introduction point for service pncas3abo2uirlci
Dec 19 12:33:50.296 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:50.297 [info] exit circ (length 3, exit tor15): tor21(open) tor19(closed) tor15(closed)
Dec 19 12:33:50.310 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:50.310 [info] internal (high-uptime) circ (length 3, exit tor5): tor22(open) tor9(open) tor5(open)
Dec 19 12:33:50.310 [info] circuit_send_next_onion_skin(): circuit built!
Dec 19 12:33:50.310 [info] rend_service_intro_has_opened(): Established circuit 17670 as introduction point for service pncas3abo2uirlci
Dec 19 12:33:50.315 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:50.315 [info] exit circ (length 3, exit tor15): tor21(open) tor19(open) tor15(closed)
Dec 19 12:33:50.326 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:50.326 [info] exit circ (length 3, exit tor15): tor21(open) tor19(open) tor15(open)
Dec 19 12:33:50.326 [info] circuit_send_next_onion_skin(): circuit built!
Dec 19 12:33:50.328 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:50.328 [info] internal (high-uptime) circ (length 3, exit tor15): tor21(open) tor3(open) tor15(open)
Dec 19 12:33:50.328 [info] circuit_send_next_onion_skin(): circuit built!
Dec 19 12:33:50.328 [info] rend_service_intro_has_opened(): Established circuit 51740 as introduction point for service upxlw4s7cpagkusq
Dec 19 12:33:50.333 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:50.333 [info] exit circ (length 3, exit tor1): tor8(open) tor15(open) tor1(open)
Dec 19 12:33:50.333 [info] circuit_send_next_onion_skin(): circuit built!
Dec 19 12:33:51.276 [info] circuit_predict_and_launch_new(): Have 2 clean circs (0 internal), need another internal circ for my hidden service.
Dec 19 12:33:51.308 [info] circuit_send_next_onion_skin(): First hop: finished sending CREATE cell to 'tor30'
Dec 19 12:33:51.317 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:51.317 [info] internal (high-uptime) circ (length 3, exit tor22): tor30(open) tor8(closed) tor22(closed)
Dec 19 12:33:51.328 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:51.328 [info] internal (high-uptime) circ (length 3, exit tor22): tor30(open) tor8(open) tor22(closed)
Dec 19 12:33:51.339 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:51.339 [info] internal (high-uptime) circ (length 3, exit tor22): tor30(open) tor8(open) tor22(open)
Dec 19 12:33:51.339 [info] circuit_send_next_onion_skin(): circuit built!
Dec 19 12:33:52.280 [info] circuit_predict_and_launch_new(): Have 3 clean circs (1 internal), need another internal circ for my hidden service.
Dec 19 12:33:52.308 [info] circuit_send_next_onion_skin(): First hop: finished sending CREATE cell to 'tor32'
Dec 19 12:33:52.317 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:52.317 [info] internal (high-uptime) circ (length 3, exit tor20): tor32(open) tor16(closed) tor20(closed)
Dec 19 12:33:52.327 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:52.327 [info] internal (high-uptime) circ (length 3, exit tor20): tor32(open) tor16(open) tor20(closed)
Dec 19 12:33:52.338 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:52.338 [info] internal (high-uptime) circ (length 3, exit tor20): tor32(open) tor16(open) tor20(open)
Dec 19 12:33:52.338 [info] circuit_send_next_onion_skin(): circuit built!
Dec 19 12:33:53.283 [info] circuit_predict_and_launch_new(): Have 4 clean circs (2 internal), need another internal circ for my hidden service.
Dec 19 12:33:53.311 [info] circuit_send_next_onion_skin(): First hop: finished sending CREATE cell to 'tor6'
Dec 19 12:33:53.319 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:53.319 [info] internal (high-uptime) circ (length 3, exit tor9): tor6(open) tor45(closed) tor9(closed)
Dec 19 12:33:53.330 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:53.330 [info] internal (high-uptime) circ (length 3, exit tor9): tor6(open) tor45(open) tor9(closed)
Dec 19 12:33:53.341 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:33:53.341 [info] internal (high-uptime) circ (length 3, exit tor9): tor6(open) tor45(open) tor9(open)
Dec 19 12:33:53.341 [info] circuit_send_next_onion_skin(): circuit built!
Dec 19 12:33:56.302 [info] connection_ap_make_bridge(): Making AP bridge to 127.0.0.1:19031 ...
Dec 19 12:33:56.302 [info] exit circ (length 3): tor21(open) tor19(open) tor15(open)
Dec 19 12:33:56.302 [info] connection_ap_handshake_send_begin(): Address/port sent, ap socket 30, n_circ_id 51741
Dec 19 12:33:56.302 [info] connection_ap_make_bridge(): ... AP bridge created and connected.
Dec 19 12:33:56.302 [info] connection_ap_make_bridge(): Making AP bridge to 127.0.0.2:19032 ...
Dec 19 12:33:56.302 [info] exit circ (length 3): tor21(open) tor19(open) tor15(open)
Dec 19 12:33:56.302 [info] connection_ap_handshake_send_begin(): Address/port sent, ap socket 32, n_circ_id 51741
Dec 19 12:33:56.302 [info] connection_ap_make_bridge(): ... AP bridge created and connected.
Dec 19 12:33:56.305 [info] connection_ap_make_bridge(): Making AP bridge to 127.0.0.1:19031 ...
Dec 19 12:33:56.305 [info] exit circ (length 3): tor21(open) tor19(open) tor15(open)
Dec 19 12:33:56.305 [info] connection_ap_handshake_send_begin(): Address/port sent, ap socket 34, n_circ_id 51741
Dec 19 12:33:56.305 [info] connection_ap_make_bridge(): ... AP bridge created and connected.
Dec 19 12:33:56.305 [info] connection_ap_make_bridge(): Making AP bridge to 127.0.0.2:19032 ...
Dec 19 12:33:56.305 [info] exit circ (length 3): tor21(open) tor19(open) tor15(open)
Dec 19 12:33:56.305 [info] connection_ap_handshake_send_begin(): Address/port sent, ap socket 36, n_circ_id 51741
Dec 19 12:33:56.305 [info] connection_ap_make_bridge(): ... AP bridge created and connected.
Dec 19 12:33:56.305 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for connect' state. Leaving it on buffer.
Dec 19 12:33:56.305 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for connect' state. Leaving it on buffer.
Dec 19 12:33:56.305 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for connect' state. Leaving it on buffer.
Dec 19 12:33:56.305 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for connect' state. Leaving it on buffer.
Dec 19 12:33:56.305 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for connect' state. Leaving it on buffer.
Dec 19 12:33:56.305 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for connect' state. Leaving it on buffer.
Dec 19 12:33:56.305 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for connect' state. Leaving it on buffer.
Dec 19 12:33:56.305 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for connect' state. Leaving it on buffer.
Dec 19 12:33:56.307 [info] connection_edge_process_relay_cell_not_open(): 'connected' received after 0 seconds.
Dec 19 12:33:56.307 [info] exit circ (length 3): tor21(open) tor19(open) tor15(open)
Dec 19 12:33:56.308 [info] connection_edge_process_relay_cell_not_open(): 'connected' received after 0 seconds.
Dec 19 12:33:56.308 [info] exit circ (length 3): tor21(open) tor19(open) tor15(open)
Dec 19 12:33:56.308 [info] connection_edge_process_relay_cell_not_open(): 'connected' received after 0 seconds.
Dec 19 12:33:56.308 [info] exit circ (length 3): tor21(open) tor19(open) tor15(open)
Dec 19 12:33:56.308 [info] connection_edge_process_relay_cell_not_open(): 'connected' received after 0 seconds.
Dec 19 12:33:56.308 [info] exit circ (length 3): tor21(open) tor19(open) tor15(open)
Dec 19 12:33:56.352 [info] connection_edge_process_relay_cell(): 30: end cell (closed normally) for stream 1935. Removing stream.
Dec 19 12:33:56.352 [info] connection_dir_client_reached_eof(): Uploading rendezvous descriptor: finished with status 200 ("Service descriptor stored")
Dec 19 12:33:56.352 [info] connection_edge_process_relay_cell(): 34: end cell (closed normally) for stream 1937. Removing stream.
Dec 19 12:33:56.352 [info] connection_edge_process_relay_cell(): 32: end cell (closed normally) for stream 1936. Removing stream.
Dec 19 12:33:56.352 [info] connection_edge_process_relay_cell(): 36: end cell (closed normally) for stream 1938. Removing stream.
Dec 19 12:33:56.352 [info] connection_dir_client_reached_eof(): Uploading rendezvous descriptor: finished with status 200 ("Service descriptor stored")
Dec 19 12:33:56.353 [info] connection_dir_client_reached_eof(): Uploading rendezvous descriptor: finished with status 200 ("Service descriptor stored")
Dec 19 12:33:56.353 [info] connection_dir_client_reached_eof(): Uploading rendezvous descriptor: finished with status 200 ("Service descriptor stored")
Dec 19 12:34:03.628 [info] rend_service_introduce(): Received INTRODUCE2 cell for service upxlw4s7cpagkusq on circ 51740.
Dec 19 12:34:03.635 [info] circuit_launch_by_extend_info(): Cannibalizing circ 'tor22' for purpose 15
Dec 19 12:34:03.637 [info] rend_service_introduce(): Accepted intro; launching circuit to 'tor19' (cookie 2952EE7E) for service upxlw4s7cpagkusq.
Dec 19 12:34:03.647 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:34:03.647 [info] internal (high-uptime) circ (length 4, exit tor19): tor30(open) tor8(open) tor22(open) tor19(open)
Dec 19 12:34:03.647 [info] circuit_send_next_onion_skin(): circuit built!
Dec 19 12:34:03.647 [info] rend_service_rendezvous_has_opened(): Done building circuit 42698 to rendezvous with cookie 2952EE7E for service upxlw4s7cpagkusq
Dec 19 12:34:04.343 [info] circuit_predict_and_launch_new(): Have 3 clean circs (2 internal), need another internal circ for my hidden service.
Dec 19 12:34:04.347 [info] circuit_send_next_onion_skin(): First hop: finished sending CREATE cell to 'tor8'
Dec 19 12:34:04.355 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:34:04.355 [info] internal (high-uptime) circ (length 3, exit tor1): tor8(open) tor31(closed) tor1(closed)
Dec 19 12:34:04.366 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:34:04.366 [info] internal (high-uptime) circ (length 3, exit tor1): tor8(open) tor31(open) tor1(closed)
Dec 19 12:34:04.378 [info] circuit_finish_handshake(): Finished building circuit hop:
Dec 19 12:34:04.378 [info] internal (high-uptime) circ (length 3, exit tor1): tor8(open) tor31(open) tor1(open)
Dec 19 12:34:04.378 [info] circuit_send_next_onion_skin(): circuit built!
Dec 19 12:34:04.482 [info] connection_edge_finished_connecting(): Exit connection to (rendezvous):80 (141.201.27.14) established.
Dec 19 12:34:04.589 [info] connection_edge_process_relay_cell(): 30: end cell (closed normally) for stream 59882. Removing stream.
Dec 19 12:34:22.640 [info] connection_edge_finished_connecting(): Exit connection to (rendezvous):80 (141.201.27.14) established.
Dec 19 12:34:23.045 [info] connection_edge_process_relay_cell(): 30: end cell (closed normally) for stream 59883. Removing stream.
Dec 19 12:34:38.304 [info] circuit_extend(): Next router (127.0.0.10:19010) not connected. Connecting.
Dec 19 12:34:47.280 [info] connection_control_process_inbuf_v0(): Detected v1 control protocol on connection (fd 33)
Dec 19 12:34:47.280 [info] handle_control_authenticate(): Authenticated control connection (33)
Dec 19 12:34:47.280 [err] signal_callback(): Catching signal TERM, exiting cleanly.
Dec 19 12:34:47.438 [info] dnsworker_main(): DNS worker exiting because Tor process closed connection (either pruned idle dnsworker or died).

comment:2 Changed 13 years ago by weasel

For my own reference, a list of cores with this error type.

Tor build C,

./tor-create-and-go-away-40/core.15110.delete_log
./tor-create-and-go-away-40/core.10553.delete_log
./tor-create-and-go-away-40/core.31487.delete_log
./tor-create-and-go-away-40/core.30076.delete_log
./tor-create-and-go-away-40/core.5372.delete_log
./tor-create-and-go-away-41/core.17708.delete_log
./tor-create-and-go-away-41/core.1913.delete_log
./tor-create-and-go-away-41/core.2301.delete_log
./tor-create-and-go-away-41/core.24664.delete_log
./tor-create-and-go-away-41/core.7266.delete_log
./tor-create-and-go-away-41/core.26522.delete_log
./tor-create-and-go-away-41/core.28730.delete_log
./tor-create-and-go-away-41/core.19063.delete_log
./tor-create-and-go-away-42/core.26779.delete_log
./tor-create-and-go-away-42/core.5194.delete_log
./tor-create-and-go-away-43/core.13189.delete_log
./tor-create-and-go-away-43/core.22063.delete_log
./tor-create-and-go-away-43/core.23322.delete_log
./tor-create-and-go-away-43/core.16203.delete_log
./tor-create-and-go-away-44/core.2352.delete_log
./tor-create-and-go-away-44/core.28049.delete_log
./tor-create-and-go-away-44/core.11547.delete_log
./tor-create-and-go-away-44/core.22907.delete_log
./tor-create-and-go-away-44/core.30032.delete_log
./tor-create-and-go-away-44/core.31319.delete_log
./tor-create-and-go-away-44/core.8491.delete_log
./tor-create-and-go-away-44/core.27423.delete_log
./tor-create-and-go-away-44/core.30319.delete_log
./tor-create-and-go-away-44/core.13356.delete_log
./tor-create-and-go-away-44/core.29507.delete_log
./tor-create-and-go-away-44/core.32105.delete_log
./tor-create-and-go-away-44/core.7856.delete_log
./tor-create-and-go-away-44/core.13437.delete_log
./tor-create-and-go-away-44/core.11668.delete_log
./tor-create-and-go-away-44/core.26207.delete_log
./tor-create-and-go-away-45/core.5993.delete_log
./tor-create-and-go-away-45/core.21358.delete_log
./tor-create-and-go-away-45/core.11499.delete_log
./tor-create-and-go-away-45/core.15661.delete_log
./tor-create-and-go-away-45/core.18636.delete_log
./tor-create-and-go-away-46/core.29983.delete_log
./tor-create-and-go-away-46/core.5086.delete_log
./tor-create-and-go-away-46/core.3580.delete_log
./tor-create-and-go-away-47/core.26033.delete_log
./tor-create-and-go-away-47/core.21237.delete_log
./tor-create-and-go-away-47/core.29383.delete_log

comment:3 Changed 13 years ago by arma

I just experienced this running 0.1.1.20 as a server. When I ^c'ed, I got:

log.c:342 delete_log: Assertion tmpl failed; aborting.

#0 0x0000002a95e43545 in raise () from /lib/libc.so.6
#1 0x0000002a95e44cce in abort () from /lib/libc.so.6
#2 0x0000000000451b5b in delete_log (victim=0x5bada0) at log.c:348
#3 0x000000000045189b in logv (severity=6, domain=32768,

funcname=0x47115d "cpuworker_main",
format=0x471580 "CPU worker exiting because Tor process closed connection (either rotated keys or died).", ap=0x41fff430) at log.c:228

#4 0x0000000000451a0f in _log_fn (severity=31779, domain=31783,

fn=0x6 <Address 0x6 out of bounds>,
format=0xffffffffffffffff <Address 0xffffffffffffffff out of bounds>)
at log.c:252

#5 0x000000000042a498 in cpuworker_main (data=0x7c23) at cpuworker.c:297
#6 0x0000000000456040 in tor_pthread_helper_fn (_data=0x7c23) at compat.c:833
#7 0x0000002a95af8b55 in start_thread () from /lib/libpthread.so.0
#8 0x0000002a95ee67f0 in clone () from /lib/libc.so.6

I just applied a minor patch to make this part more resilient to bugs. In
general, it looks like we're going to have to put a mutex around some of our
log stuff, since it's shared between threads.

comment:4 Changed 13 years ago by arma

Oh -- and I was using "numcpus 2" at the time. That probably encourages the race to appear.

comment:5 Changed 12 years ago by nickm

Has anybody seen this since June?

Also, note that this is happening because we got an EOF from writing to the log.
We should probably never call delete_log() because of this from anywhere besides
the main thread.

comment:6 Changed 12 years ago by nickm

It's been nearly a year since this bug was observed in the wild, and r10395 makes the
worst aspects of its behavior go away. I'm adding an XXXX to log.c about the mutex issue
(since AFAIC that's now a code-strictness issue, not an actual bug) and closing this bug.

comment:7 Changed 12 years ago by nickm

flyspray2trac: bug closed.

comment:8 Changed 7 years ago by nickm

Component: Tor RelayTor
Note: See TracTickets for help on using tickets.