[Pkg-privacy-maintainers] Bug#865368: torsocks: procmail spawned by mpop in torsocks fails with "Operation not permitted"

Sat Sep 2 17:46:42 UTC 2017

Control: tag -1 - moreinfo
Control: tag -1 forwarded dgoulet at ev0ke.net

Hi David!

Can you please have a look at this bug report?

Full discussion and debug log: https://bugs.debian.org/865368

Please let us know if you need additional info :)

Nick:
>> 1. try to reproduce with torsocks 2.2.0-2 (that landed in sid
>>    yesterday);

> I can reproduce exactly the same thing with 2.2.0-2

>> 2. if this still fails, retry with `torsocks --debug' so I have more
>>    information to forward upstream.

> Done, log attached.

> 1503579551 DEBUG torsocks[29232]: Logging subsytem initialized. Level 5, file (null), time 1 (in init_logging() at torsocks.c:303)
> 1503579551 DEBUG torsocks[29232]: Config file not provided by TORSOCKS_CONF_FILE. Using default /etc/tor/torsocks.conf (in config_file_read() at config-file.c:543)
> 1503579551 DEBUG torsocks[29232]: Config file setting tor address to 127.0.0.1 (in conf_file_set_tor_address() at config-file.c:298)
> 1503579551 DEBUG torsocks[29232]: Config file setting tor port to 9050 (in conf_file_set_tor_port() at config-file.c:254)
> 1503579551 DEBUG torsocks[29232]: [config] Onion address range set to 127.42.42.0/24 (in set_onion_info() at config-file.c:108)
> 1503579551 DEBUG torsocks[29232]: Config file /etc/tor/torsocks.conf opened and parsed. (in config_file_read() at config-file.c:572)
> 1503579551 DEBUG torsocks[29232]: [fclose] Close caught for fd 3 (in tsocks_fclose() at fclose.c:45)
> 1503579551 DEBUG torsocks[29232]: [onion] Pool init with subnet 127.42.42.0 and mask 24 (in onion_pool_init() at onion.c:104)
> 1503579551 DEBUG torsocks[29232]: [onion] Pool initialized with base 0, max_pos 255 and size 8 (in onion_pool_init() at onion.c:132)
> 1503579551 DEBUG torsocks[29232]: [fclose] Close caught for fd 3 (in tsocks_fclose() at fclose.c:45)
> 1503579551 DEBUG torsocks[29236]: Logging subsytem initialized. Level 5, file (null), time 1 (in init_logging() at torsocks.c:303)
> 1503579551 DEBUG torsocks[29236]: Config file not provided by TORSOCKS_CONF_FILE. Using default /etc/tor/torsocks.conf (in config_file_read() at config-file.c:543)
> 1503579551 DEBUG torsocks[29236]: Config file setting tor address to 127.0.0.1 (in conf_file_set_tor_address() at config-file.c:298)
> 1503579551 DEBUG torsocks[29236]: Config file setting tor port to 9050 (in conf_file_set_tor_port() at config-file.c:254)
> 1503579551 DEBUG torsocks[29236]: [config] Onion address range set to 127.42.42.0/24 (in set_onion_info() at config-file.c:108)
> 1503579551 DEBUG torsocks[29236]: Config file /etc/tor/torsocks.conf opened and parsed. (in config_file_read() at config-file.c:572)
> 1503579551 DEBUG torsocks[29236]: [fclose] Close caught for fd 3 (in tsocks_fclose() at fclose.c:45)
> 1503579551 DEBUG torsocks[29236]: [onion] Pool init with subnet 127.42.42.0 and mask 24 (in onion_pool_init() at onion.c:104)
> 1503579551 DEBUG torsocks[29236]: [onion] Pool initialized with base 0, max_pos 255 and size 8 (in onion_pool_init() at onion.c:132)
> 1503579551 DEBUG torsocks[29236]: [close] Close caught for fd 0 (in tsocks_close() at close.c:33)
> 1503579551 DEBUG torsocks[29236]: [close] Close caught for fd 3 (in tsocks_close() at close.c:33)
> 1503579551 DEBUG torsocks[29237]: Logging subsytem initialized. Level 5, file (null), time 1 (in init_logging() at torsocks.c:303)
> 1503579551 DEBUG torsocks[29237]: Config file not provided by TORSOCKS_CONF_FILE. Using default /etc/tor/torsocks.conf (in config_file_read() at config-file.c:543)
> 1503579551 DEBUG torsocks[29237]: Config file setting tor address to 127.0.0.1 (in conf_file_set_tor_address() at config-file.c:298)
> 1503579551 DEBUG torsocks[29237]: Config file setting tor port to 9050 (in conf_file_set_tor_port() at config-file.c:254)
> 1503579551 DEBUG torsocks[29237]: [config] Onion address range set to 127.42.42.0/24 (in set_onion_info() at config-file.c:108)
> 1503579551 DEBUG torsocks[29237]: Config file /etc/tor/torsocks.conf opened and parsed. (in config_file_read() at config-file.c:572)
> 1503579551 DEBUG torsocks[29237]: [fclose] Close caught for fd 3 (in tsocks_fclose() at fclose.c:45)
> 1503579551 DEBUG torsocks[29237]: [onion] Pool init with subnet 127.42.42.0 and mask 24 (in onion_pool_init() at onion.c:104)
> 1503579551 DEBUG torsocks[29237]: [onion] Pool initialized with base 0, max_pos 255 and size 8 (in onion_pool_init() at onion.c:132)
> 1503579551 DEBUG torsocks[29237]: [close] Close caught for fd 3 (in tsocks_close() at close.c:33)
> 1503579551 DEBUG torsocks[29237]: [close] Close caught for fd 3 (in tsocks_close() at close.c:33)
> 1503579551 DEBUG torsocks[29237]: [onion] Destroying onion pool containing 0 entry (in onion_pool_destroy() at onion.c:148)
> 1503579551 DEBUG torsocks[29237]: [fclose] Close caught for fd 2 (in tsocks_fclose() at fclose.c:45)
> 1503579551 DEBUG torsocks[29236]: [close] Close caught for fd 10 (in tsocks_close() at close.c:33)
> 1503579551 DEBUG torsocks[29236]: [onion] Destroying onion pool containing 0 entry (in onion_pool_destroy() at onion.c:148)
> 1503579551 DEBUG torsocks[29236]: [fclose] Close caught for fd 2 (in tsocks_fclose() at fclose.c:45)
> 1503579551 DEBUG torsocks[29232]: [fclose] Close caught for fd 3 (in tsocks_fclose() at fclose.c:45)
> 1503579551 DEBUG torsocks[29232]: [getaddrinfo] Requesting viper hostname (in tsocks_getaddrinfo() at getaddrinfo.c:44)
> 1503579551 DEBUG torsocks[29232]: Resolving viper on the Tor network (in tsocks_tor_resolve() at torsocks.c:544)
> 1503579551 DEBUG torsocks[29232]: Setting up a connection to the Tor network on fd 3 (in setup_tor_connection() at torsocks.c:367)
> 1503579551 DEBUG torsocks[29232]: Socks5 sending method ver: 5, nmethods 0x01, methods 0x00 (in socks5_send_method() at socks5.c:229)
> 1503579551 DEBUG torsocks[29232]: Socks5 received method ver: 5, method 0x00 (in socks5_recv_method() at socks5.c:262)
> 1503579551 DEBUG torsocks[29232]: [socks5] Resolve for viper sent successfully (in socks5_send_resolve_request() at socks5.c:639)
> 1503579551 ERROR torsocks[29232]: Unable to resolve. Status reply: 4 (in socks5_recv_resolve_reply() at socks5.c:683)
> 1503579551 DEBUG torsocks[29232]: [getaddrinfo] Requesting mail.messagingengine.com hostname (in tsocks_getaddrinfo() at getaddrinfo.c:44)
> 1503579551 DEBUG torsocks[29232]: Resolving mail.messagingengine.com on the Tor network (in tsocks_tor_resolve() at torsocks.c:544)
> 1503579551 DEBUG torsocks[29232]: Setting up a connection to the Tor network on fd 3 (in setup_tor_connection() at torsocks.c:367)
> 1503579551 DEBUG torsocks[29232]: Socks5 sending method ver: 5, nmethods 0x01, methods 0x00 (in socks5_send_method() at socks5.c:229)
> 1503579551 DEBUG torsocks[29232]: Socks5 received method ver: 5, method 0x00 (in socks5_recv_method() at socks5.c:262)
> 1503579551 DEBUG torsocks[29232]: [socks5] Resolve for mail.messagingengine.com sent successfully (in socks5_send_resolve_request() at socks5.c:639)
> 1503579551 DEBUG torsocks[29232]: [socks5] Resolve reply received successfully (in socks5_recv_resolve_reply() at socks5.c:716)
> 1503579551 DEBUG torsocks[29232]: [getaddrinfo] Node mail.messagingengine.com resolved to 66.111.4.52 (in tsocks_getaddrinfo() at getaddrinfo.c:107)
> 1503579551 DEBUG torsocks[29232]: [socket] Creating socket with domain 2, type 1 and protocol 6 (in tsocks_socket() at socket.c:33)
> 1503579551 DEBUG torsocks[29232]: Connect caught on fd 3 (in tsocks_connect() at connect.c:118)
> 1503579551 DEBUG torsocks[29232]: [connect] Socket family AF_INET and type 1 (in tsocks_validate_socket() at connect.c:77)
> 1503579551 DEBUG torsocks[29232]: [onion] Finding onion entry for IP 66.111.4.52 (in onion_entry_find_by_addr() at onion.c:268)
> 1503579551 DEBUG torsocks[29232]: Connecting to the Tor network on fd 3 (in tsocks_connect_to_tor() at torsocks.c:472)
> 1503579551 DEBUG torsocks[29232]: Setting up a connection to the Tor network on fd 3 (in setup_tor_connection() at torsocks.c:367)
> 1503579551 DEBUG torsocks[29232]: Socks5 sending method ver: 5, nmethods 0x01, methods 0x00 (in socks5_send_method() at socks5.c:229)
> 1503579551 DEBUG torsocks[29232]: Socks5 received method ver: 5, method 0x00 (in socks5_recv_method() at socks5.c:262)
> 1503579551 DEBUG torsocks[29232]: Socks5 sending connect request to fd 3 (in socks5_send_connect_request() at socks5.c:465)
> 1503579552 DEBUG torsocks[29232]: Socks5 received connect reply - ver: 5, rep: 0x00, atype: 0x01 (in socks5_recv_connect_reply() at socks5.c:525)
> 1503579552 DEBUG torsocks[29232]: Socks5 connection is successful. (in socks5_recv_connect_reply() at socks5.c:529)
> 1503579552 DEBUG torsocks[29232]: [fclose] Close caught for fd 4 (in tsocks_fclose() at fclose.c:45)
> 1503579552 DEBUG torsocks[29232]: [socket] Creating socket with domain 2, type 2050 and protocol 0 (in tsocks_socket() at socket.c:33)
> 1503579552 DEBUG torsocks[29232]: IPv4/v6 non TCP socket denied. Tor network can't handle it. (in tsocks_socket() at socket.c:69)
> 1503579555 DEBUG torsocks[29232]: [fclose] Close caught for fd 5 (in tsocks_fclose() at fclose.c:45)
> 1503579555 DEBUG torsocks[29405]: Logging subsytem initialized. Level 5, file (null), time 1 (in init_logging() at torsocks.c:303)
> 1503579555 DEBUG torsocks[29405]: Config file not provided by TORSOCKS_CONF_FILE. Using default /etc/tor/torsocks.conf (in config_file_read() at config-file.c:543)
> 1503579555 DEBUG torsocks[29405]: Config file setting tor address to 127.0.0.1 (in conf_file_set_tor_address() at config-file.c:298)
> 1503579555 DEBUG torsocks[29405]: Config file setting tor port to 9050 (in conf_file_set_tor_port() at config-file.c:254)
> 1503579555 DEBUG torsocks[29405]: [config] Onion address range set to 127.42.42.0/24 (in set_onion_info() at config-file.c:108)
> 1503579555 DEBUG torsocks[29405]: Config file /etc/tor/torsocks.conf opened and parsed. (in config_file_read() at config-file.c:572)
> 1503579555 DEBUG torsocks[29405]: [fclose] Close caught for fd 6 (in tsocks_fclose() at fclose.c:45)
> 1503579555 DEBUG torsocks[29405]: [onion] Pool init with subnet 127.42.42.0 and mask 24 (in onion_pool_init() at onion.c:104)
> 1503579555 DEBUG torsocks[29405]: [onion] Pool initialized with base 0, max_pos 255 and size 8 (in onion_pool_init() at onion.c:132)
> sh: 1: /usr/bin/procmail: Operation not permitted
> 1503579555 DEBUG torsocks[29406]: [onion] Destroying onion pool containing 0 entry (in onion_pool_destroy() at onion.c:148)
> 1503579555 DEBUG torsocks[29406]: [fclose] Close caught for fd 2 (in tsocks_fclose() at fclose.c:45)
> 1503579555 DEBUG torsocks[29405]: [onion] Destroying onion pool containing 0 entry (in onion_pool_destroy() at onion.c:148)
> 1503579555 DEBUG torsocks[29405]: [fclose] Close caught for fd 2 (in tsocks_fclose() at fclose.c:45)
> 1503579555 DEBUG torsocks[29232]: [fclose] Close caught for fd 5 (in tsocks_fclose() at fclose.c:45)
> 1503579555 DEBUG torsocks[29232]: [fclose] Close caught for fd 4 (in tsocks_fclose() at fclose.c:45)
> 1503579555 DEBUG torsocks[29232]: [close] Close caught for fd 3 (in tsocks_close() at close.c:33)
> 1503579555 DEBUG torsocks[29232]: [close] Close connection putting back ref (in tsocks_close() at close.c:51)
> mpop: /usr/bin/procmail -f '%F' -d $USER returned exit status 2
> mpop: error during mail retrieval (account default from /home/nick/.mpoprc)
> 1503579555 DEBUG torsocks[29232]: [onion] Destroying onion pool containing 0 entry (in onion_pool_destroy() at onion.c:148)
> 1503579555 DEBUG torsocks[29232]: [fclose] Close caught for fd 2 (in tsocks_fclose() at fclose.c:45)

Cheers,
-- 
intrigeri