Opened 2 years ago

Closed 20 months ago

#22719 closed defect (fixed)

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

Reported by: toralf Owned by: nickm
Priority: Medium Milestone: Tor: 0.3.1.x-final
Component: Core Tor/Tor Version: Tor: 0.3.1.7
Severity: Normal Keywords:
Cc: ahf Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

Got this today (used latest git version) at a stable Gentoo Linux server:

Jun 24 11:01:47.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)

Child Tickets

Attachments (1)

0001-Try-a-little-harder-to-make-sure-we-never-call-tor_c.patch (1.6 KB) - added by nickm 2 years ago.

Download all attachments as: .zip

Change History (21)

comment:1 Changed 2 years ago by toralf

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).

comment:2 Changed 2 years ago by toralf

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 ...

comment:3 Changed 2 years ago by nickm

Milestone: Tor: 0.3.1.x-final

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: ".

comment:4 Changed 2 years ago by toralf

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).

comment:5 Changed 2 years ago by nickm

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.

comment:6 Changed 2 years ago by toralf

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).

comment:7 Changed 2 years ago by nickm

Owner: set to nickm
Status: newaccepted

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.

comment:8 Changed 2 years ago by nickm

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?

comment:9 Changed 2 years ago by nickm

Status: acceptedneeds_review

comment:10 Changed 2 years ago by ahf

Cc: ahf added

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.

comment:11 in reply to:  10 ; Changed 2 years ago by 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.

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 ?

Last edited 2 years ago by toralf (previous) (diff)

comment:12 in reply to:  11 Changed 2 years ago by nickm

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.

comment:13 Changed 2 years ago by ahf

Status: needs_reviewmerge_ready

comment:14 Changed 2 years ago by nickm

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?

comment:15 Changed 2 years ago by nickm

Resolution: fixed
Status: merge_readyclosed

comment:16 Changed 21 months ago by Hello71

Resolution: fixed
Status: closedreopened
Version: Tor: unspecifiedTor: 0.3.1.7

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

comment:17 Changed 21 months ago by nickm

Resolution: fixed
Status: reopenedclosed

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.

comment:18 Changed 20 months ago by weasel

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

comment:19 Changed 20 months ago by yurivict271

Resolution: fixed
Status: closedreopened

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

I reopened it.

comment:20 Changed 20 months ago by nickm

Resolution: fixed
Status: reopenedclosed

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.

Note: See TracTickets for help on using tickets.