Opened 4 weeks ago

Closed 2 weeks ago

#24972 closed defect (fixed)

Bug: src/or/hs_descriptor.c:2357: hs_desc_encode_descriptor: Non-fatal assertion !(ret < 0) failed.

Reported by: asn Owned by:
Priority: Medium Milestone: Tor: 0.3.3.x-final
Component: Core Tor/Tor Version:
Severity: Normal Keywords: tor-hs, prop224, review-group-31
Cc: Actual Points:
Parent ID: Points: 2
Reviewer: asn Sponsor:

Description (last modified by asn)

My HSv3 is unable to encode its own descriptor with the following fail:

Jan 21 08:00:49.000 [info] connection_free_minimal(): Freeing linked Socks connection [open] with 0 bytes on inbuf, 0 on outbuf.
Jan 21 08:00:49.000 [info] handle_response_upload_hsdesc(): Uploaded hidden service descriptor (status 200 ("HS descriptor stored successfully."))
Jan 21 08:00:49.000 [info] handle_response_upload_hsdesc(): Uploading hidden service descriptor: finished with status 200 ("HS descriptor stored successfully.")
Jan 21 08:00:49.000 [info] connection_free_minimal(): Freeing linked Directory connection [client finished] with 0 bytes on inbuf, 0 on outbuf.
Jan 21 08:00:49.000 [info] circuit_finish_handshake(): Finished building circuit hop:
Jan 21 08:00:49.000 [info] internal (high-uptime) circ (length 4, last hop damita): $E2920D7419B7601CF82D43400D042DA70E0675B2(open) $CA58EB617C6CA2F351AEFD56C84B8A7AF7704B22(open) $0E3D3FCE26F6969B7AE80E4CA6C4CFA97988F31E(open) $A9F7185499C5784E35B5C25744ED4AB75437CE5D(open)
Jan 21 08:00:49.000 [info] entry_guards_note_guard_success(): Recorded success for primary confirmed guard papadouka ($E2920D7419B7601CF82D43400D042DA70E0675B2)
Jan 21 08:00:49.000 [info] circuit_build_no_more_hops(): circuit built!
Jan 21 08:00:49.000 [info] pathbias_count_build_success(): Got success count 224.332749/291.637758 for guard papadouka ($E2920D7419B7601CF82D43400D042DA70E0675B2)
Jan 21 08:01:06.000 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 58 to 86.106.137.6:443 (E2920D7419B7601CF82D43400D042DA70E0675B2) after 5296 ms. Delta -4ms
Jan 21 08:01:12.000 [info] routerlist_remove_old_routers(): We have 0 live routers and 0 old router descriptors.
Jan 21 08:01:19.000 [info] or_state_save(): Saved state to "/home/f/.tor/state"
Jan 21 08:01:25.000 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 58 to 86.106.137.6:443 (E2920D7419B7601CF82D43400D042DA70E0675B2) after 5996 ms. Delta 2ms
Jan 21 08:01:32.000 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 58 to 86.106.137.6:443 (E2920D7419B7601CF82D43400D042DA70E0675B2) after 6840 ms. Delta -2ms
Jan 21 08:01:43.000 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 58 to 86.106.137.6:443 (E2920D7419B7601CF82D43400D042DA70E0675B2) after 2096 ms. Delta 0ms
Jan 21 08:01:51.000 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 58 to 86.106.137.6:443 (E2920D7419B7601CF82D43400D042DA70E0675B2) after 7912 ms. Delta 0ms
Jan 21 08:01:57.000 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 58 to 86.106.137.6:443 (E2920D7419B7601CF82D43400D042DA70E0675B2) after 6456 ms. Delta 0ms
Jan 21 08:02:05.000 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 58 to 86.106.137.6:443 (E2920D7419B7601CF82D43400D042DA70E0675B2) after 7952 ms. Delta 3ms
Jan 21 08:02:07.000 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 58 to 86.106.137.6:443 (E2920D7419B7601CF82D43400D042DA70E0675B2) after 2280 ms. Delta 1ms
Jan 21 08:02:12.000 [info] routerlist_remove_old_routers(): We have 0 live routers and 0 old router descriptors.
Jan 21 08:02:20.000 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 58 to 86.106.137.6:443 (E2920D7419B7601CF82D43400D042DA70E0675B2) after 3756 ms. Delta 2ms
Jan 21 08:02:33.000 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 58 to 86.106.137.6:443 (E2920D7419B7601CF82D43400D042DA70E0675B2) after 8344 ms. Delta 0ms
Jan 21 08:03:00.000 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 58 to 86.106.137.6:443 (E2920D7419B7601CF82D43400D042DA70E0675B2) after 4508 ms. Delta 2ms
Jan 21 08:03:04.000 [info] run_upload_descriptor_event(): Initiating upload for hidden service current descriptor for service j2eiu2izwjpazjevu4xs3muaif3jzex3nnvnu677vz2fypmzccvhhiid with 3/3 introduction points.
Jan 21 08:03:04.000 [info] close_directory_connections(): Closed 0 active service directory connections for descriptor 9btQxrMpxWDJwnf1TU6U+5vcPmPdD2OPBVAKKmRLr7I of service j2eiu2izwjpazjevu4xs3muaif3jzex3nnvnu677vz2fypmzccvhhiid
Jan 21 08:03:04.000 [info] crypto_strongest_rand_fallback(): Reading entropy from "/dev/urandom"
Jan 21 08:03:04.000 [info] crypto_strongest_rand_fallback(): Reading entropy from "/dev/urandom"
Jan 21 08:03:04.000 [warn] Invalid signature for service descriptor signing key.
Jan 21 08:03:04.000 [warn] tor_bug_occurred_(): Bug: src/or/hs_descriptor.c:2357: hs_desc_encode_descriptor: Non-fatal assertion !(ret < 0) failed. (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug: Non-fatal assertion !(ret < 0) failed in hs_desc_encode_descriptor at src/or/hs_descriptor.c:2357. Stack trace: (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     ./tor/src/or/tor(log_backtrace+0x42) [0x7ffa9cd66ac2] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     ./tor/src/or/tor(tor_bug_occurred_+0xb7) [0x7ffa9cd81cd7] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     ./tor/src/or/tor(hs_desc_encode_descriptor+0xb2) [0x7ffa9cd4d782] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     ./tor/src/or/tor(hs_service_run_scheduled_events+0x21f3) [0x7ffa9cd570d3] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     ./tor/src/or/tor(+0x4ca31) [0x7ffa9cc30a31] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     ./tor/src/or/tor(+0x6cdc0) [0x7ffa9cc50dc0] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     /usr/lib/x86_64-linux-gnu/libevent-2.0.so.5(event_base_loop+0x7fc) [0x7ffa9c2673dc] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     ./tor/src/or/tor(do_main_loop+0x25c) [0x7ffa9cc34c9c] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     ./tor/src/or/tor(tor_run_main+0x265) [0x7ffa9cc360b5] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     ./tor/src/or/tor(tor_main+0x3a) [0x7ffa9cc2f71a] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     ./tor/src/or/tor(main+0x19) [0x7ffa9cc2f489] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1) [0x7ffa9b45a2b1] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     ./tor/src/or/tor(_start+0x2a) [0x7ffa9cc2f4da] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] tor_bug_occurred_(): Bug: src/or/hs_service.c:2245: upload_descriptor_to_hsdir: Non-fatal assertion !(hs_desc_encode_descriptor(desc->desc, &desc->signing_kp, &encoded_desc) < 0) failed. (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug: Non-fatal assertion !(hs_desc_encode_descriptor(desc->desc, &desc->signing_kp, &encoded_desc) < 0) failed in upload_descriptor_to_hsdir at src/or/hs_service.c:2245. Stack trace: (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     ./tor/src/or/tor(log_backtrace+0x42) [0x7ffa9cd66ac2] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     ./tor/src/or/tor(tor_bug_occurred_+0xb7) [0x7ffa9cd81cd7] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     ./tor/src/or/tor(hs_service_run_scheduled_events+0x23e7) [0x7ffa9cd572c7] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     ./tor/src/or/tor(+0x4ca31) [0x7ffa9cc30a31] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     ./tor/src/or/tor(+0x6cdc0) [0x7ffa9cc50dc0] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     /usr/lib/x86_64-linux-gnu/libevent-2.0.so.5(event_base_loop+0x7fc) [0x7ffa9c2673dc] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     ./tor/src/or/tor(do_main_loop+0x25c) [0x7ffa9cc34c9c] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     ./tor/src/or/tor(tor_run_main+0x265) [0x7ffa9cc360b5] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     ./tor/src/or/tor(tor_main+0x3a) [0x7ffa9cc2f71a] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     ./tor/src/or/tor(main+0x19) [0x7ffa9cc2f489] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1) [0x7ffa9b45a2b1] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)
Jan 21 08:03:04.000 [warn] Bug:     ./tor/src/or/tor(_start+0x2a) [0x7ffa9cc2f4da] (on Tor 0.3.3.0-alpha-dev d69c8f7117a5975a)

That started happening 4 days after I started up Tor and it persists up to today: my HS is still unable to create its own desc...

FWIW, the only difference from the past is that I've been using vanguards but that should not influence the signing of the desc....

Child Tickets

Attachments (1)

bug24972.log.gz (511.8 KB) - added by asn 4 weeks ago.

Download all attachments as: .zip

Change History (10)

comment:1 Changed 4 weeks ago by asn

Description: modified (diff)

comment:2 Changed 4 weeks ago by asn

Also uploading some info logs.

It seems like the problem occurs only for the current descriptor, wheras the next one gets uploaded normally. You can also see various info-level HSDir descriptor rejection logs even from before the non-fatal assert started appearing.

It's a bit sad we don't have more precise logs from tor_cert_checksig() so that we know how the signature check failed. It could even be an expiration issue, but that wouldn't make much sense since the cert is made on demand before the desc encode...

Changed 4 weeks ago by asn

Attachment: bug24972.log.gz added

comment:3 Changed 4 weeks ago by nickm

please save a copy of all your state if this is still happening: it might be important for reproducing this.

comment:4 Changed 4 weeks ago by nickm

Status: newneeds_review

My branch bug24972_diagnostic_032 adds some logs that might help diagnose here.

comment:5 Changed 4 weeks ago by nickm

Keywords: review-group-31 added

comment:6 Changed 4 weeks ago by asn

Status: needs_reviewmerge_ready

LGTM!

Should we let this ticket open until someone hits this issue with the debugging patch?

comment:7 Changed 3 weeks ago by asn

Reviewer: asn

comment:8 in reply to:  6 Changed 3 weeks ago by nickm

Status: merge_readyneeds_information

Replying to asn:

LGTM!

Thanks! I've merged it to 0.3.2 and forward.

Should we let this ticket open until someone hits this issue with the debugging patch?

Yeah, I think that's about all we can do. (unless you can reproduce the bug somehow?)

comment:9 Changed 2 weeks ago by dgoulet

Resolution: fixed
Status: needs_informationclosed

Honestly, I'm running HSv3 .onion everywhere for months now and I haven't seen this yet so I propose we close it and if it appears again, we re-open. Else, it just sits in our queue while unable to do anything about it... :S

Please re-open if that is not what you think should happen.

Note: See TracTickets for help on using tickets.