Bug: src/common/compress.c:576: tor_compress_process:

changed milestone to %Tor: 0.3.1.x-final

added component::core tor/tor milestone::Tor: 0.3.1.x-final owner::nickm priority::medium resolution::fixed severity::normal status::closed type::defect version::tor 0.3.1.7 labels

FWIW:

Jun 24 11:34:08.000 [warn] tor_bug_occurred_(): Bug: src/common/compress.c:576: tor_compress_process: Non-fatal assertion !((rv == TOR_COMPRESS_OK) && *in_len == in_len_orig && *out_len == out_len_orig) failed. (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 11:34:08.000 [warn] Bug: Non-fatal assertion !((rv == TOR_COMPRESS_OK) && *in_len == in_len_orig && *out_len == out_len_orig) failed in tor_compress_process at src/common/compress.c:576. Stack trace: (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 11:34:08.000 [warn] Bug:     /usr/bin/tor(log_backtrace+0x51) [0x56431e2839f1] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 11:34:08.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc5) [0x56431e29e0c5] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 11:34:08.000 [warn] Bug:     /usr/bin/tor(tor_compress_process+0x146) [0x56431e2a7406] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 11:34:08.000 [warn] Bug:     /usr/bin/tor(write_to_buf_compress+0xd5) [0x56431e1d3615] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 11:34:08.000 [warn] Bug:     /usr/bin/tor(connection_write_to_buf_impl_+0xbd) [0x56431e21914d] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 11:34:08.000 [warn] Bug:     /usr/bin/tor(connection_dirserv_flushed_some+0x1aa) [0x56431e24faaa] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 11:34:08.000 [warn] Bug:     /usr/bin/tor(+0x102e4d) [0x56431e213e4d] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 11:34:08.000 [warn] Bug:     /usr/bin/tor(+0x10ca4d) [0x56431e21da4d] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 11:34:08.000 [warn] Bug:     /usr/bin/tor(+0x4c7dd) [0x56431e15d7dd] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 11:34:08.000 [warn] Bug:     /usr/lib64/libevent-2.1.so.6(+0x2369a) [0x7fe302f4b69a] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 11:34:08.000 [warn] Bug:     /usr/lib64/libevent-2.1.so.6(event_base_loop+0x57f) [0x7fe302f4c5ef] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 11:34:08.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0x24d) [0x56431e15e98d] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 11:34:08.000 [warn] Bug:     /usr/bin/tor(tor_main+0x1c2d) [0x56431e16236d] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 11:34:08.000 [warn] Bug:     /usr/bin/tor(main+0x28) [0x56431e159d68] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 11:34:08.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xfc) [0x7fe301adb6fc] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 11:34:08.000 [warn] Bug:     /usr/bin/tor(_start+0x29) [0x56431e159db9] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 11:34:08.000 [warn] write_to_buf failed. Closing connection (fd -1).

I should mention that the logged git commit id is wrong. I do use patched version, meaning on top of 0.3.1.-alpha I putted :

git diff tor-0.3.1.3-alpha..remotes/origin/master -- . ':!scripts/maint' ':!doc' ':!contrib' ':!changes' ':ChangeLog' ':!Release*' | sudo tee /etc/portage/patches/net-vpn/tor/maint.patch

The same Bug occurs with

git diff tor-0.3.1.3-alpha..remotes/origin/maint-0.3.1 ...

I introduced that check in 9328bd524e38befe240fd729a9febb4dfe8b5be4, thinking that it should never trigger: if it's happening, it does represent a real bug of some type, I think.

I've added a log statement in 6caf924605fd that might help diagnose this. If you're running from latest master, and you see the bug again, please past the output here, including the line that starts with "More info on the bug: ".

Trac:
Milestone: N/A to Tor: 0.3.1.x-final

Jun 24 17:55:15.000 [notice] Tor 0.3.2.0-alpha-dev (git-dc47d936d47ffc25) opening log file.
Jun 24 17:55:20.000 [warn] tor_bug_occurred_(): Bug: src/common/compress.c:576: tor_compress_process: Non-fatal assertion !((rv == TOR_COMPRESS_OK) && *in_len == in_len_orig && *out_len == out_len_orig) failed. (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 17:55:20.000 [warn] Bug: Non-fatal assertion !((rv == TOR_COMPRESS_OK) && *in_len == in_len_orig && *out_len == out_len_orig) failed in tor_compress_process at src/common/compress.c:576. Stack trace: (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 17:55:20.000 [warn] Bug:     /usr/bin/tor(log_backtrace+0x51) [0x55e739e3f9f1] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 17:55:20.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc5) [0x55e739e5a0c5] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 17:55:20.000 [warn] Bug:     /usr/bin/tor(tor_compress_process+0x146) [0x55e739e63406] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 17:55:20.000 [warn] Bug:     /usr/bin/tor(write_to_buf_compress+0xd5) [0x55e739d8f615] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 17:55:20.000 [warn] Bug:     /usr/bin/tor(connection_write_to_buf_impl_+0xbd) [0x55e739dd514d] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 17:55:20.000 [warn] Bug:     /usr/bin/tor(connection_dirserv_flushed_some+0x1aa) [0x55e739e0baaa] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 17:55:20.000 [warn] Bug:     /usr/bin/tor(+0x138577) [0x55e739e05577] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 17:55:20.000 [warn] Bug:     /usr/bin/tor(connection_dir_process_inbuf+0x728) [0x55e739dff758] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 17:55:20.000 [warn] Bug:     /usr/bin/tor(+0x10c969) [0x55e739dd9969] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 17:55:20.000 [warn] Bug:     /usr/bin/tor(+0x4c7dd) [0x55e739d197dd] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 17:55:20.000 [warn] Bug:     /usr/lib64/libevent-2.1.so.6(+0x2369a) [0x7fb181d8969a] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 17:55:20.000 [warn] Bug:     /usr/lib64/libevent-2.1.so.6(event_base_loop+0x57f) [0x7fb181d8a5ef] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 17:55:20.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0x24d) [0x55e739d1a98d] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 17:55:20.000 [warn] Bug:     /usr/bin/tor(tor_main+0x1c2d) [0x55e739d1e36d] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 17:55:20.000 [warn] Bug:     /usr/bin/tor(main+0x28) [0x55e739d15d68] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 17:55:20.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xfc) [0x7fb1809196fc] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 17:55:20.000 [warn] Bug:     /usr/bin/tor(_start+0x29) [0x55e739d15db9] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 17:55:20.000 [warn] More info on the bug: *in_len == in_len_orig == 0, *out_len == out_len_orig == 4048
Jun 24 17:55:20.000 [warn] write_to_buf failed. Closing connection (fd -1).

That's certainly strange. I've added more logging, to see where this is happening. I wonder what the value of "finish" and "method" are here.

Jun 24 20:04:38.000 [warn] tor_bug_occurred_(): Bug: src/common/compress.c:576: tor_compress_process: Non-fatal assertion !((rv == TOR_COMPRESS_OK) && *in_len == in_len_orig && *out_len == out_len_orig) failed. (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 20:04:38.000 [warn] Bug: Non-fatal assertion !((rv == TOR_COMPRESS_OK) && *in_len == in_len_orig && *out_len == out_len_orig) failed in tor_compress_process at src/common/compress.c:576. Stack trace: (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 20:04:38.000 [warn] Bug:     /usr/bin/tor(log_backtrace+0x51) [0x564206ca39f1] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 20:04:38.000 [warn] Bug:     /usr/bin/tor(tor_bug_occurred_+0xc5) [0x564206cbe0c5] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 20:04:38.000 [warn] Bug:     /usr/bin/tor(tor_compress_process+0x154) [0x564206cc7414] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 20:04:38.000 [warn] Bug:     /usr/bin/tor(write_to_buf_compress+0xd5) [0x564206bf3615] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 20:04:38.000 [warn] Bug:     /usr/bin/tor(connection_write_to_buf_impl_+0xbd) [0x564206c3914d] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 20:04:38.000 [warn] Bug:     /usr/bin/tor(connection_dirserv_flushed_some+0x1aa) [0x564206c6faaa] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 20:04:38.000 [warn] Bug:     /usr/bin/tor(+0x102e4d) [0x564206c33e4d] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 20:04:38.000 [warn] Bug:     /usr/bin/tor(+0x10ca4d) [0x564206c3da4d] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 20:04:38.000 [warn] Bug:     /usr/bin/tor(+0x4c7dd) [0x564206b7d7dd] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 20:04:38.000 [warn] Bug:     /usr/lib64/libevent-2.1.so.6(+0x2369a) [0x7f83424be69a] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 20:04:38.000 [warn] Bug:     /usr/lib64/libevent-2.1.so.6(event_base_loop+0x57f) [0x7f83424bf5ef] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 20:04:38.000 [warn] Bug:     /usr/bin/tor(do_main_loop+0x24d) [0x564206b7e98d] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 20:04:38.000 [warn] Bug:     /usr/bin/tor(tor_main+0x1c2d) [0x564206b8236d] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 20:04:38.000 [warn] Bug:     /usr/bin/tor(main+0x28) [0x564206b79d68] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 20:04:38.000 [warn] Bug:     /lib64/libc.so.6(__libc_start_main+0xfc) [0x7f834104e6fc] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 20:04:38.000 [warn] Bug:     /usr/bin/tor(_start+0x29) [0x564206b79db9] (on Tor 0.3.2.0-alpha-dev dc47d936d47ffc25)
Jun 24 20:04:38.000 [warn] More info on the bug: method == deflated, finish == 0,  *in_len == in_len_orig == 0, *out_len == out_len_orig == 4048
Jun 24 20:04:38.000 [warn] write_to_buf failed. Closing connection (fd -1).

Okay; it's "deflated" so it's not a new problem; it's probably some longstanding bug. It's probably not a harmful bug in this case, but we should clean it up, so that we can keep the warning check in the code: that warning check prevents a pretty damaging class of bugs.

The issue here is that finish == 0 and in_len == 0; we don't actually expect any progress in that case.

Trac:
Owner: N/A to nickm
Status: new to accepted

Trac:
0001-Try-a-little-harder-to-make-sure-we-never-call-tor_c.patch

I have attached a patch which might fix the problem. It's based on 0.3.1 but it should apply fine to master as well. It's also in my branch bug22719_031.

Please let me know if this patch fixes the problem for you? And if not, what do the error logs look like now?

Trac:
Status: accepted to needs_review

I think the patch looks good, but I think it would be useful to see if toralf can reproduce the issue even after the patch is applied to their Tor instance.

Trac:
Cc: N/A to ahf

Replying to ahf:

I think the patch looks good, but I think it would be useful to see if toralf can reproduce the issue even after the patch is applied to their Tor instance. It is ok now for about 4 hours - but eventually after 24 hours I can tell, whether it is fixed.

FWIW I do argue that the issue started here immediately when I switched from vanilla kernel 4.11.5 to 4.11.7 (I skipped 4.11.6, that had no impressive fixes IMO). Given that, could the issue be uncovered by the stack-gap-CVE-thingy ?

Replying to toralf:

Replying to ahf:

I think the patch looks good, but I think it would be useful to see if toralf can reproduce the issue even after the patch is applied to their Tor instance. It is ok now for about 4 hours - but eventually after 24 hours I can tell, whether it is fixed.

Awesome! Please let us know how it goes.

FWIW I do argue that the issue started here immediately when I switched from vanilla kernel 4.11.5 to 4.11.7 (I skipped 4.11.6, that had no impressive fixes IMO). Given that, could the issue be uncovered by the stack-gap-CVE-thingy ?

I don't think so; I can't imagine how. I believe the reason this started appearing was probably just 9328bd524e38befe240fd729a9febb4dfe8b5be4 from last tuesday.

Trac:
Status: needs_review to merge_ready

I have merged this to maint-0.3.1 and master. But please let us know if there are remaining bugs, and reopen if this bug is not in fact fixed?

Trac:
Status: merge_ready to closed
Resolution: N/A to fixed

I am hitting this assertion now in the released stable on Arch Linux.

Trac:
Status: closed to reopened
Version: Tor: unspecified to Tor: 0.3.1.7
Resolution: fixed to N/A

Please reopen this if it happens in 0.3.2.2-alpha or 0.3.1.8 ? We believe that those versions, when released, will not have this bug.

Trac:
Resolution: N/A to fixed
Status: reopened to closed

We are hitting this in 0.3.1.7 on Debian. cf. https://bugs.debian.org/878172

FreeBSD also still hits this bug in 0.3.1.7: https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=223033

I reopened it.

Trac:
Resolution: fixed to N/A
Status: closed to reopened

It is indeed expected that this is happening in 0.3.1.7: the fix is scheduled for 0.3.1.8. It should be out later this week or early next.

Trac:
Resolution: N/A to fixed
Status: reopened to closed

closed

mentioned in issue #23551 (moved)

moved to tpo/core/tor#22719 (closed)

mentioned in issue tpo/core/tor#23551 (closed)

Bug: src/common/compress.c:576: tor_compress_process:

Child items ...

Activity