circuit_package_relay_cell(): Bug: outgoing relay cell has n_chan==NULL. Dropping.
Don't know whether the above message is related to bugs #8093 (moved) or #6252 (moved) (if so, apologies!), but decided to report this anyway. The full message is:
[warn] {BUG} circuit_package_relay_cell(): Bug: outgoing relay cell has n_chan==NULL. Dropping.
There are no particular circumstances which I've noticed this message to appear (in fact, I've noticed it only when checking the tor logs a couple of hours later) - tor has been running more than a day at that point.
Trac:
Username: mr-4
Activity
changed milestone to %Tor: 0.2.9.x-final
added 029-backport 030-backport 031-backport annoyance component::core tor/tor harmless? logging milestone::Tor: 0.2.9.x-final needs-analysis owner::nickm points::3 priority::high reporter::mr-4 resolution::fixed reviewer::isis severity::major status::closed tor-relay type::defect version::tor 0.2.4.9-alpha labels
Hm. I think the best we can do here is some kind of diagnostic branch to improve the bug message. Somebody is calling relay_send_command_from_edge on a circuit that hasn't actually negotiated with anything yet. (Do you have optimistic data enabled?)
Branch "bug8185_diagnostic" in my public repository tries to improve the log message in a way that might help to track this down.
Trac:
Status: new to needs_review
Replying to nickm:
Hm. I think the best we can do here is some kind of diagnostic branch to improve the bug message. Somebody is calling relay_send_command_from_edge on a circuit that hasn't actually negotiated with anything yet. (Do you have optimistic data enabled?) What is "optimistic data"?
Branch "bug8185_diagnostic" in my public repository tries to improve the log message in a way that might help to track this down. Do I apply that on top of the latest tor version?
Trac:
Username: mr-4-
Merged the diagnostic branch to 0.2.4. Let's see if this causes anything we can fix. Putting this in needs-information pending more info.
(You probably aren't using optimistic data unless you know about it. Generally, yes, you can test branches by applying them to the latest tor)
Trac:
Status: needs_review to needs_information -
Nothing to report so far for the above - I am not seeing this message after about 3 days of continuous tor operation, though I've got 2 other bug messages appearing, which are described in bugs #8858 (moved) and #8859 (moved).
I'll keep you posted if something turns up in my logs.
Trac:
Username: mr-4 
This likely was a dup of #8024 (moved).
-
Don't know whether the message below is related to this bug, but thought to report it here: Soon after tor start, I get this:
Aug 31 22:59:04.000 [warn] {OR} connection_edge_process_relay_cell (at origin) failed. Aug 31 22:59:04.000 [warn] {PROTOCOL} circuit_receive_relay_cell (backward) failed. Closing.
It only happened about 3 times in quick succession and then stopped. I am still on Tor version 0.2.4.14-alpha (git-f5729b8c1d45933f)
Trac:
Username: mr-4 relay_send_command_from_edge_(streamid_t stream_id, circuit_t *circ, uint8_t relay_command, const char *payload, size_t payload_len, crypt_path_t *cpath_layer, const char *filename, int lineno) { cell_t cell; relay_header_t rh; cell_direction_t cell_direction; /* XXXX NM Split this function into a separate versions per circuit type? */ tor_assert(circ); tor_assert(payload_len <= RELAY_PAYLOAD_SIZE); + if (circ->marked_for_close) /* XXX bug, race, normal? */ + return -1;-
Marking these as must-fix-before-028-rc.
Actually, some of them may not need to get 'fixed' before the rc, but I believe that they should either get fixed, or we should have a good explanation of why they don't need to get fixed.
Trac:
Keywords: tor-relay 024-backport deleted, 024-backport, tor-relay, must-fix-before-028-rc added Adding myself as the reviewer because I started hitting this bug at some point between 0.2.7.x and 0.2.8.x while running my patches for #7144 (moved) under chutney (seemingly unrelated to my patches).
Trac:
Reviewer: N/A to isisThis bug message depends circuit in question and data client plans to append there. If entry relay
lost n_chan (connection to middle relay attached to used circuit) then itsends destroy cell for some reason to client. Such cell processed bycommand_process_destroy_cell, thus marks circuit for close, clears n_chan, while keeps strteams attached to marked for close circuit. If any those stream's data client plans to package before circuit freed then message triggered.thus marks circuit for close, clears n_chan, while keeps strteams attached to marked for close circuit. No. Seems like wrong patch.
circuit_mark_for_closecallsorigin_circuit_t *ocirc = TO_ORIGIN_CIRCUIT(circ); edge_connection_t *conn; for (conn=ocirc->p_streams; conn; conn=conn->next_stream) connection_edge_destroy(circ->n_circ_id, conn); ocirc->p_streams = NULL;Marked for close circuit has no attached streams.
Trac:
Status: needs_review to needs_informationif (CIRCUIT_IS_ORIGIN(circ)) { - if (pathbias_check_close(TO_ORIGIN_CIRCUIT(circ), reason) == -1) { + if (pathbias_check_close(TO_ORIGIN_CIRCUIT(circ), reason) == -1 && + circ->n_chan) { /* Don't close it yet, we need to test it first */ return; }Maybe?
Trac:
Status: needs_information to needs_revisionOn 0.2.8.x, sending a destroy cell from the entry to the client while the client is trying to send data still doesn't seem to trigger this for me…
Since a bunch of the code for marking circuits for close and freeing them changed in 0.2.8, I agree that trying to track this bug down in N different tor versions is probably going to be too confusing. We should probably just focus on trying to find it in
maint-0.2.8?I'm putting this ticket back into 'needs_information' state, and hopefully more people will come along and try to figure out where this bug is coming from.
Trac:
Status: needs_review to needs_informationReplying to isis:
On 0.2.8.x, sending a destroy cell from the entry to the client while the client is trying to send data still doesn't seem to trigger this for me…
Since a bunch of the code for marking circuits for close and freeing them changed in 0.2.8, I agree that trying to track this bug down in N different tor versions is probably going to be too confusing. We should probably just focus on trying to find it in
maint-0.2.8?I'm putting this ticket back into 'needs_information' state, and hopefully more people will come along and try to figure out where this bug is coming from.
if (!chan) { log_warn(LD_BUG,"outgoing relay cell sent from %s:%d has n_chan==NULL." " Dropping.", filename, lineno); + if (circ->marked_for_close) { + log_warn(LD_BUG, + "Circuit n_circ_id %u was marked for close at %s:%d" + " for reason %d", (unsigned)circ->n_circ_id, + circ->marked_for_close_file, circ->marked_for_close, + circ->marked_for_close_orig_reason); + } return 0; /* just drop it */ }
#19136 (moved) is a duplicate.
Trac:
Cc: N/A to user33331111#19711 (moved) is a newer report of the same issue, happening on 0.3.x - hopefully we can work there and close both.
I've just noticed it on my latest stable Tor version. I have no idea what triggered this bug.
Mar 22 XX:XX:23.000 [warn] circuit_package_relay_cell(): Bug: outgoing relay cell sent from ../src/or/relay.c:701 has n_chan==NULL. Dropping. (on Tor 0.2.9.10 ) Mar 22 XX:XX:23.000 [warn] circuit_package_relay_cell(): Bug: outgoing relay cell sent from ../src/or/relay.c:701 has n_chan==NULL. Dropping. (on Tor 0.2.9.10 ) Mar 22 XX:XX:23.000 [warn] circuit_package_relay_cell(): Bug: outgoing relay cell sent from ../src/or/relay.c:701 has n_chan==NULL. Dropping. (on Tor 0.2.9.10 )
-
Kicking this into 0.3.2. The fix may be to edit the log message so it only logs above PROTOCOL_WARN if our favorite theory turns out to be false.
Trac:
Keywords: tor-relay deleted, tor-relay logging needs-analysis added
Status: needs_information to new
Milestone: Tor: unspecified to Tor: 0.3.2.x-final For recent duplicate tickets: #19136 (moved) #19711 (moved) #23105 (moved)
Trac:
Keywords: tor-relay logging needs-analysis deleted, tor-relay logging needs-analysis harmless? annoyance added
Priority: Medium to High
Milestone: Tor: 0.3.2.x-final to Tor: 0.3.3.x-final#23679 (moved) is a duplicate.
Got it again, seems it's affecting many of us,
[warn] circuit_package_relay_cell(): Bug: outgoing relay cell sent from src/or/relay.c:836 has n_chan==NULL. Dropping. (on Tor 0.3.1.5-alpha 83389502ee631465) [warn] circuit_package_relay_cell(): Bug: outgoing relay cell sent from src/or/relay.c:836 has n_chan==NULL. Dropping. (on Tor 0.3.1.5-alpha 83389502ee631465)Trac:
Severity: Normal to Major
Milestone: Tor: 0.3.3.x-final to Tor: 0.3.2.x-finalOkay, the stack trace that Nick added may prove useful, here are the ones that popped up for me:
[warn] circuit_package_relay_cell(): Bug: outgoing relay cell sent from src/or/relay.c:825 has n_chan==NULL. Dropping. (on Tor 0.3.2.1-alpha ) [warn] Bug: . Stack trace: (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(log_backtrace+0x42) [0x55a025ae0c72] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(relay_send_command_from_edge_+0x50f) [0x55a0259d598f] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(connection_edge_send_command+0x62) [0x55a0259d5c72] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(connection_edge_package_raw_inbuf+0x1fa) [0x55a0259d5f9a] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(connection_edge_process_inbuf+0xd7) [0x55a025a702c7] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(+0x1071e9) [0x55a025a681e9] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(+0x4e1f1) [0x55a0259af1f1] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/libevent-2.0.so.5(event_base_loop+0x812) [0x7ff8cbc66002] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(do_main_loop+0x23d) [0x55a0259b028d] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(tor_main+0x1c15) [0x55a0259b3c05] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(main+0x19) [0x55a0259abab9] (on Tor 0.3.2.1-alpha ) [warn] Bug: /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1) [0x7ff8cadfd3f1] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(+0x4ab09) [0x55a0259abb09] (on Tor 0.3.2.1-alpha ) [warn] circuit_package_relay_cell(): Bug: outgoing relay cell sent from src/or/relay.c:825 has n_chan==NULL. Dropping. (on Tor 0.3.2.1-alpha ) [warn] Bug: . Stack trace: (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(log_backtrace+0x42) [0x55a025ae0c72] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(relay_send_command_from_edge_+0x50f) [0x55a0259d598f] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(connection_edge_send_command+0x62) [0x55a0259d5c72] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(connection_edge_package_raw_inbuf+0x1fa) [0x55a0259d5f9a] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(connection_edge_process_inbuf+0xd7) [0x55a025a702c7] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(+0x1071e9) [0x55a025a681e9] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(+0x4e1f1) [0x55a0259af1f1] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/libevent-2.0.so.5(event_base_loop+0x812) [0x7ff8cbc66002] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(do_main_loop+0x23d) [0x55a0259b028d] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(tor_main+0x1c15) [0x55a0259b3c05] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(main+0x19) [0x55a0259abab9] (on Tor 0.3.2.1-alpha ) [warn] Bug: /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1) [0x7ff8cadfd3f1] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(+0x4ab09) [0x55a0259abb09] (on Tor 0.3.2.1-alpha ) [warn] circuit_package_relay_cell(): Bug: outgoing relay cell sent from src/or/relay.c:825 has n_chan==NULL. Dropping. (on Tor 0.3.2.1-alpha ) [warn] Bug: . Stack trace: (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(log_backtrace+0x42) [0x55a025ae0c72] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(relay_send_command_from_edge_+0x50f) [0x55a0259d598f] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(connection_edge_send_command+0x62) [0x55a0259d5c72] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(connection_edge_package_raw_inbuf+0x1fa) [0x55a0259d5f9a] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(connection_edge_process_inbuf+0xd7) [0x55a025a702c7] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(+0x1071e9) [0x55a025a681e9] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(+0x4e1f1) [0x55a0259af1f1] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/libevent-2.0.so.5(event_base_loop+0x812) [0x7ff8cbc66002] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(do_main_loop+0x23d) [0x55a0259b028d] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(tor_main+0x1c15) [0x55a0259b3c05] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(main+0x19) [0x55a0259abab9] (on Tor 0.3.2.1-alpha ) [warn] Bug: /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1) [0x7ff8cadfd3f1] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(+0x4ab09) [0x55a0259abb09] (on Tor 0.3.2.1-alpha ) [warn] circuit_package_relay_cell(): Bug: outgoing relay cell sent from src/or/relay.c:825 has n_chan==NULL. Dropping. (on Tor 0.3.2.1-alpha ) [warn] Bug: . Stack trace: (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(log_backtrace+0x42) [0x55a025ae0c72] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(relay_send_command_from_edge_+0x50f) [0x55a0259d598f] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(connection_edge_send_command+0x62) [0x55a0259d5c72] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(connection_edge_package_raw_inbuf+0x1fa) [0x55a0259d5f9a] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(connection_edge_process_inbuf+0xd7) [0x55a025a702c7] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(+0x10763b) [0x55a025a6863b] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(+0x4e1f1) [0x55a0259af1f1] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/libevent-2.0.so.5(event_base_loop+0x812) [0x7ff8cbc66002] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(do_main_loop+0x23d) [0x55a0259b028d] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(tor_main+0x1c15) [0x55a0259b3c05] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(main+0x19) [0x55a0259abab9] (on Tor 0.3.2.1-alpha ) [warn] Bug: /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1) [0x7ff8cadfd3f1] (on Tor 0.3.2.1-alpha ) [warn] Bug: /home/alfred/tor-browser_en-US/Browser/TorBrowser/Tor/tor(+0x4ab09) [0x55a0259abb09] (on Tor 0.3.2.1-alpha )-
Interesting. It looks like the callstack here is:
- circuit_package_relay_cell()
- relay_send_command_from_edge_()
- relay_send_command_from_edge()
- connection_edge_package_raw_inbuf()
- connection_edge_process_inbuf()
What else do we know?
- This is an entry connection attached to an origin circuit.
- As of connection_edge_process_inbuf(), the connection was in state AP_CONN_STATE_OPEN or AP_CONN_STATE_CONNECT_WAIT. (or else we wouldn't have called package_raw_inbuf())
- As of connection_edge_package_raw_inbuf(), the connection was not marked for close. (Or else the function would have exited.)
- By the time we reach the bottom of the callstack, the circuit's n_chan was NULL, which shouldn't be possible.
I think what I'd most like to know at this point is the exact status of the circuit -- is it completely corrupted, marked for close, or in-progress for a build?
I'm guessing that this connection was once attached to a working circuit (otherwise the earlier attempt to send the BEGIN cell would have failed with the same error) and then the circuit became non-working.
What if the channel becomes closed, and so channel_closed() we call circuit_unlink_all_from_channel()? That will clear the n_chan field of the circuit, and mark the circuit. But the streams attached to the circuit won't get marked for close or have their circuits removed until circuit_about_to_free() calls connection_edge_destroy().
I'm going to go with the theory that the circuit is marked, and add logging to catch in case it isn't. Cooking up a patch now...
Trac:
Status: new to accepted
Owner: N/A to nickm
