torsocks should log errors to stderr and not stdout

torsocks 2.0.0-rc3

I get stuff like this on stdout:

[Feb 28 14:05:16] WARNING torsocks[22952]: Non TCP inet socket denied. Tor network can't handle it. (in tsocks_socket() at socket.c:40)

Logging to stdout interferes with the output of the underlying program, and is generally a bad idea.

added component::core tor/torsocks owner::dgoulet priority::medium resolution::not a bug severity::normal status::closed type::defect labels

Trac:
Owner: ioerror to dgoulet
Status: new to assigned

Hrm that's a bit weird because the default is to use stderr... If you look at src/common/log.c +166, a check is made on stderr if it exists and valid else it's going to use 0 (stdout).

Is there at some point anything that closes stderr in your use case that could prevent torsocks from using it?

My use case is parcimonie, I will ping the author:

$ aptitude show parcimonie torsocks | grep Version
Version: 0.8.1-1
Version: 2.0.0~rc3-1
$ parcimonie --verbose 2>/dev/null
[Mar 02 22:16:09] WARNING torsocks[9119]: Non TCP inet socket denied. Tor network can't handle it. (in tsocks_socket() at socket.c:40)
[Mar 02 22:16:09] WARNING torsocks[9119]: Non TCP inet socket denied. Tor network can't handle it. (in tsocks_socket() at socket.c:40)

Replying to infinity0:

My use case is parcimonie, I will ping the author:

I'm sorry, I still did not have time to look into this (nor to test torsocks 2.x at all, btw). Pinging me about it every 2-4 weeks might help.

My plan is to try and reproduce it, and then extract a minimal test case (if I suspect the problem is in an underlying library) or fix my code (if the problem is there). I would certainly not mind any help, by the way. The thing is written in Modern Perl.

Reassigning to me as I'm the one who is committed to do the next action. Feel free to revert if this was not appropriate use of these crazy new things I can click on Trac :)

Trac:
Owner: dgoulet to intrigeri

I can't reproduce that with parcimonie 0.8.3-1 and torsocks 2.0.0-1 (which I'll upload to Debian unstable right now). infinity0, is there anything specific in your setup that might trigger this?

Trac:
Status: assigned to needs_information

Any update on that? I confirm that it's going on stderr.

I've looked again at what parcimonie does when fetching keys, and was not able to find any place where it would itself output torsocks-related stuff to stdout. On GnuPG errors, parcimonie always sends captured output to stderr. So, infinity0: can you please provide instructions to reproduce this bug in a clean environment?

Trac:
Status: needs_information to assigned
Owner: intrigeri to infinity0

$ sudo sed -i -e 's/9050/9059/g' /etc/tor/torsocks.conf # force an error from torsocks

$ parcimonie --verbose 2>/dev/null
[Apr 23 11:08:39] PERROR torsocks[29673]: socks5 libc connect: Connection refused (in socks5_connect() at socks5.c:185)
gpgkeys: HTTP fetch error 6: Could not resolve host: pool.sks-keyservers.net

Using versions from Debian sid:

$ apt-cache policy torsocks
torsocks:
  Installed: 2.0.0-3
  Candidate: 2.0.0-3
  Version table:
 *** 2.0.0-3 0
        990 http://ftp.uk.debian.org/debian/ testing/main amd64 Packages
        500 http://ftp.uk.debian.org/debian/ unstable/main amd64 Packages
        100 /var/lib/dpkg/status
     1.3-3~precise 0
        500 http://ppa.launchpad.net/guardianproject/ppa/ubuntu/ precise/main amd64 Packages

$ apt-cache policy parcimonie 
parcimonie:
  Installed: 0.8.4-1
  Candidate: 0.8.4-1
  Version table:
 *** 0.8.4-1 0
        990 http://ftp.uk.debian.org/debian/ testing/main amd64 Packages
        500 http://ftp.uk.debian.org/debian/ unstable/main amd64 Packages
        100 /var/lib/dpkg/status
     0.7.1-1+deb7u1 0
        500 http://security.debian.org/ stable/updates/main amd64 Packages

Just pinging to ask if the "reproducing" steps I gave actually work for you guys, or whether it only works on my machine or if I am going crazy..

Replying to infinity0:

Just pinging to ask if the "reproducing" steps I gave actually work for you guys, or whether it only works on my machine or if I am going crazy..

Yay, yay, I'll do that. Just so you know: generally, pinging me every two weeks is the sweet spot; pinging me 28 hours after sending the requested info is a little bit stressful. Take care :)

Trac:
Owner: infinity0 to intrigeri

OK, I can reproduce that. Thanks!

On current Debian unstable, after breaking torsocks.conf like infinity0 did:

$ torsocks gpg --recv-keys A63BB098
gpg: requesting key A63BB098 from hkps server hkps.pool.sks-keyservers.net
[Apr 25 16:34:44] PERROR torsocks[1923]: socks5 libc connect: Connection refused (in socks5_connect() at socks5.c:185)
gpgkeys: HTTP fetch error 6: Could not resolve host: hkps.pool.sks-keyservers.net
gpg: no valid OpenPGP data found.
gpg: Total number processed: 0
toto@sid-desktop:~$ torsocks gpg --recv-keys A63BB098 2>/dev/null
[Apr 25 16:34:54] PERROR torsocks[1927]: socks5 libc connect: Connection refused (in socks5_connect() at socks5.c:185)
gpgkeys: HTTP fetch error 6: Could not resolve host: hkps.pool.sks-keyservers.net

and:

$ torsocks gpg --recv-keys A63BB098 2>/dev/null
[Apr 25 16:37:50] PERROR torsocks[2168]: socks5 libc connect: Connection refused (in socks5_connect() at socks5.c:185)
gpgkeys: HTTP fetch error 6: Could not resolve host: hkps.pool.sks-keyservers.net

So it looks like both torsocks and gpgkeys send some error output to stdout, and parcimonie isn't at fault here => reassigning to David.

Trac:
Owner: intrigeri to dgoulet

I can confirm that torsocks does write errors on stderr with the gpg test case in last comment:

16512 write16512 write(2, "[Jun 13 17:19:04] PERROR torsock"..., 120) = 120 (2, "[Jun 13 17:19:04] PERROR torsock"..., 120) = 120

So I think here the issue is a multi process one. In the strace I see that gpg calls:

16512 execve("/usr/lib/gnupg/gpgkeys_hkp", ["/usr/lib/gnupg/gpgkeys_hkp"], [/* 56 vars */] <unfinished ...>

... and for that process, 2>/dev/null seems to not being applied. That's possibly an issue with torsocks that is the redirection to devnull is not given to the gpg process (maybe?)...

Trac:
Status: assigned to needs_information
Reviewer: N/A to N/A
Severity: N/A to Normal
Sponsor: N/A to N/A

Testing without torsocks (/usr/bin/gpg --recv-keys AAAAAAAB, i.e. a keyid that's not on keyservers currently) suggests that torsocks does pass the redirection to gpg, but that one doesn't pass it to gpgkeys_hkp. So in the end, it might be a bug in gpg, and not in torsocks.

Trac:
Resolution: N/A to not a bug
Status: needs_information to closed

closed

moved to tpo/core/torsocks#11090 (closed)