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

Thu Aug 24 13:05:25 UTC 2017

Hi intrigeri, thanks for looking into this.

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