Tor fails to start, apparmor policy error operation="change_onexec" info="label not found"

[ghost]

Steps to Reproduce:

1. This is a fresh install Ubuntu 16.04 64bit

Additional Details:

Log output from Ansible or other relevant services (link to Gist for longer output):

TASK [tor-bridge : Wait until obfs4proxy information has shown up in its state file]
fatal: [localhost]: FAILED! => {"changed": false, "elapsed": 300, "failed": true, "msg": "Timeout when waiting for search string node-id in /var/lib/tor/pt_state/obfs4_state.json"}
RUNNING HANDLER [rsyslog : Restart rsyslog]
RUNNING HANDLER [openconnect : Restart ocserv]
RUNNING HANDLER [l2tp-ipsec : Restart Libreswan]
RUNNING HANDLER [l2tp-ipsec : Restart xl2tpd]
RUNNING HANDLER [dnsmasq : Restart dnsmasq]
RUNNING HANDLER [openvpn : Restart OpenVPN]
RUNNING HANDLER [stunnel : Restart stunnel]
RUNNING HANDLER [ssh : Restart SSH]
RUNNING HANDLER [tinyproxy : Restart Tinyproxy]
to retry, use: --limit @/root/streisand/playbooks/localhost.retry
PLAY RECAP
localhost : ok=190 changed=174 unreachable=0 failed=1

Target Cloud Provider: LeaseWeb

Operating System of target host: Ubuntu 16.04 64bit

Operating System of client: Localhost

Version of Ansible, using ansible --version : ansible 2.3.1.0

config file = /root/streisand/ansible.cfg
configured module search path = Default w/o overrides
python version = 2.7.12 (default, Nov 19 2016, 06:48:10) [GCC 5.4.0 20160609]

[cpu]

@NanoG6 What is the output from git rev-parse HEAD in the Streisand directory you git clone'd?

[ghost]

git rev-parse HEAD
975e2cf

[cpu]

@NanoG6 Very strange. I thought we had squashed this bug w/ that commit. Can you share the output from:

• ps aux | grep tor
• journalctl -b --no-pager | grep -i tor | tail -n50

(As an aside: It's late in my time-zone, I'll have to pick this issue up again tomorrow, I'm signing off shortly)

[ghost]

Hi @cpu thanks for your prompt reply. Yes I thought this issue has been solved by latest commit, but still no luck.

root@LSW:~/streisand# ps aux | grep tor
root 1936 0.0 0.0 14228 984 pts/0 S+ 02:23 0:00 grep --color=auto tor

root@LSW:~/streisand# journalctl -b --no-pager | grep -i tor | tail -n50
Jul 05 01:53:16 LSW tor[1665]: Jul 05 01:53:16.061 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
Jul 05 01:53:16 LSW tor[1665]: Jul 05 01:53:16.061 [notice] Read configuration file "/usr/share/tor/tor-service-defaults-torrc".
Jul 05 01:53:16 LSW tor[1665]: Jul 05 01:53:16.061 [notice] Read configuration file "/etc/tor/torrc".
Jul 05 01:53:16 LSW tor[1665]: Configuration was valid
Jul 05 01:53:16 LSW audit[1671]: AVC apparmor="DENIED" operation="change_onexec" info="label not found" error=-2 profile="unconfined" name="system_tor" pid=1671 comm="(tor)"
Jul 05 01:53:16 LSW kernel: audit: type=1400 audit(1499219596.072:5): apparmor="DENIED" operation="change_onexec" info="label not found" error=-2 profile="unconfined" name="system_tor" pid=1671 comm="(tor)"
Jul 05 01:53:16 LSW systemd[1671]: tor@default.service: Failed at step APPARMOR spawning /usr/bin/tor: No such file or directory
Jul 05 01:53:16 LSW systemd[1]: tor@default.service: Main process exited, code=exited, status=231/APPARMOR
Jul 05 01:53:16 LSW systemd[1]: tor@default.service: Unit entered failed state.
Jul 05 01:53:16 LSW systemd[1]: tor@default.service: Failed with result 'exit-code'.
Jul 05 01:53:16 LSW ansible-command[1669]: Invoked with creates=/etc/tor/bridge_nickname executable=None _uses_shell=True _raw_params=grep -v -P "[\x80-\xFF]" /usr/share/dict/american-english-huge | sed -e "s/'//" | shuf -n 2 | xargs | sed -e 's/ //' | cut -c 1-16 > /etc/tor/bridge_nickname removes=None warn=True chdir=None
Jul 05 01:53:16 LSW systemd[1]: tor@default.service: Service hold-off time over, scheduling restart.
Jul 05 01:53:16 LSW tor[1686]: Jul 05 01:53:16.307 [notice] Tor 0.3.0.9 (git-100816d92ab5664d) running on Linux with Libevent 2.0.21-stable, OpenSSL 1.0.2g and Zlib 1.2.8.
Jul 05 01:53:16 LSW tor[1686]: Jul 05 01:53:16.311 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
Jul 05 01:53:16 LSW tor[1686]: Jul 05 01:53:16.311 [notice] Read configuration file "/usr/share/tor/tor-service-defaults-torrc".
Jul 05 01:53:16 LSW tor[1686]: Jul 05 01:53:16.311 [notice] Read configuration file "/etc/tor/torrc".
Jul 05 01:53:16 LSW tor[1686]: Configuration was valid
Jul 05 01:53:16 LSW audit[1691]: AVC apparmor="DENIED" operation="change_onexec" info="label not found" error=-2 profile="unconfined" name="system_tor" pid=1691 comm="(tor)"
Jul 05 01:53:16 LSW kernel: audit: type=1400 audit(1499219596.324:6): apparmor="DENIED" operation="change_onexec" info="label not found" error=-2 profile="unconfined" name="system_tor" pid=1691 comm="(tor)"
Jul 05 01:53:16 LSW systemd[1691]: tor@default.service: Failed at step APPARMOR spawning /usr/bin/tor: No such file or directory
Jul 05 01:53:16 LSW systemd[1]: tor@default.service: Main process exited, code=exited, status=231/APPARMOR
Jul 05 01:53:16 LSW systemd[1]: tor@default.service: Unit entered failed state.
Jul 05 01:53:16 LSW systemd[1]: tor@default.service: Failed with result 'exit-code'.
Jul 05 01:53:16 LSW systemd[1]: tor@default.service: Service hold-off time over, scheduling restart.
Jul 05 01:53:16 LSW tor[1707]: Jul 05 01:53:16.557 [notice] Tor 0.3.0.9 (git-100816d92ab5664d) running on Linux with Libevent 2.0.21-stable, OpenSSL 1.0.2g and Zlib 1.2.8.
Jul 05 01:53:16 LSW tor[1707]: Jul 05 01:53:16.561 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
Jul 05 01:53:16 LSW tor[1707]: Jul 05 01:53:16.561 [notice] Read configuration file "/usr/share/tor/tor-service-defaults-torrc".
Jul 05 01:53:16 LSW tor[1707]: Jul 05 01:53:16.561 [notice] Read configuration file "/etc/tor/torrc".
Jul 05 01:53:16 LSW tor[1707]: Configuration was valid
Jul 05 01:53:16 LSW audit[1712]: AVC apparmor="DENIED" operation="change_onexec" info="label not found" error=-2 profile="unconfined" name="system_tor" pid=1712 comm="(tor)"
Jul 05 01:53:16 LSW kernel: audit: type=1400 audit(1499219596.580:7): apparmor="DENIED" operation="change_onexec" info="label not found" error=-2 profile="unconfined" name="system_tor" pid=1712 comm="(tor)"
Jul 05 01:53:16 LSW systemd[1712]: tor@default.service: Failed at step APPARMOR spawning /usr/bin/tor: No such file or directory
Jul 05 01:53:16 LSW systemd[1]: tor@default.service: Main process exited, code=exited, status=231/APPARMOR
Jul 05 01:53:16 LSW systemd[1]: tor@default.service: Unit entered failed state.
Jul 05 01:53:16 LSW systemd[1]: tor@default.service: Failed with result 'exit-code'.
Jul 05 01:53:16 LSW ansible-command[1704]: Invoked with warn=True executable=None _uses_shell=False _raw_params=cat /etc/tor/bridge_nickname removes=None creates=None chdir=None
Jul 05 01:53:16 LSW systemd[1]: tor@default.service: Service hold-off time over, scheduling restart.
Jul 05 01:53:16 LSW systemd[1]: tor@default.service: Start request repeated too quickly.
Jul 05 01:53:16 LSW ansible-stat[1725]: Invoked with checksum_algorithm=sha1 get_checksum=True path=/etc/tor/torrc checksum_algo=sha1 follow=True get_md5=False get_mime=True get_attributes=True
Jul 05 01:53:16 LSW ansible-stat[1739]: Invoked with checksum_algorithm=sha1 get_checksum=True path=/etc/tor/torrc checksum_algo=sha1 follow=False get_md5=False get_mime=True get_attributes=True
Jul 05 01:53:17 LSW ansible-copy[1750]: Invoked with src=/root/.ansible/tmp/ansible-tmp-1499219596.79-33335123060184/source directory_mode=None force=True remote_src=None dest=/etc/tor/torrc selevel=None seuser=None serole=None setype=None group=root content=NOT_LOGGING_PARAMETER unsafe_writes=None delimiter=None original_basename=torrc.j2 mode=420 follow=True owner=root regexp=None validate=None attributes=None backup=False
Jul 05 01:53:17 LSW ansible-stat[1761]: Invoked with checksum_algorithm=sha1 get_checksum=True path=/etc/apparmor.d/local/system_tor checksum_algo=sha1 follow=False get_md5=False get_mime=True get_attributes=True
Jul 05 01:53:17 LSW ansible-copy[1779]: Invoked with src=/root/.ansible/tmp/ansible-tmp-1499219597.16-29951194024581/source directory_mode=None force=True remote_src=None unsafe_writes=None selevel=None seuser=None setype=None group=root content=NOT_LOGGING_PARAMETER dest=/etc/apparmor.d/local/system_tor serole=None original_basename=apparmor-local-override delimiter=None mode=420 regexp=None owner=root follow=False validate=None attributes=None backup=False
Jul 05 01:53:17 LSW ansible-replace[1787]: Invoked with src=None directory_mode=None force=None remote_src=None unsafe_writes=None selevel=None regexp=^([\s]*)/usr/bin/(obfs4?proxy) PUx,$ seuser=None setype=None replace=\1/usr/bin/\2 ix, content=NOT_LOGGING_PARAMETER serole=None delimiter=None mode=None follow=False owner=None path=/etc/apparmor.d/abstractions/tor validate=None attributes=None backup=True group=None
Jul 05 01:53:17 LSW ansible-command[1794]: Invoked with warn=True executable=None _uses_shell=False _raw_params=apparmor_parser -r /etc/apparmor.d/system_tor removes=None creates=None chdir=None
Jul 05 01:53:17 LSW audit[1796]: AVC apparmor="STATUS" operation="profile_load" profile="unconfined" name="system_tor" pid=1796 comm="apparmor_parser"
Jul 05 01:53:17 LSW kernel: audit: type=1400 audit(1499219597.808:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="system_tor" pid=1796 comm="apparmor_parser"
Jul 05 01:53:17 LSW ansible-systemd[1803]: Invoked with no_block=False name=tor enabled=None daemon_reload=False state=restarted user=False masked=None
Jul 05 01:53:17 LSW systemd[1]: tor@default.service: Start request repeated too quickly.
Jul 05 01:53:18 LSW ansible-wait_for[1814]: Invoked with active_connection_states=['ESTABLISHED', 'SYN_SENT', 'SYN_RECV', 'FIN_WAIT1', 'FIN_WAIT2', 'TIME_WAIT'] state=started connect_timeout=5 delay=0 host=127.0.0.1 sleep=1 timeout=300 exclude_hosts=None search_regex=node-id path=/var/lib/tor/pt_state/obfs4_state.json port=None

[cpu]

@NanoG6 It does seem to be another apparmor related problem:

Jul 05 01:53:16 LSW audit[1691]: AVC apparmor="DENIED" operation="change_onexec" info="label not found" error=-2 profile="unconfined" name="system_tor" pid=1691 comm="(tor)"
Jul 05 01:53:16 LSW kernel: audit: type=1400 audit(1499219596.324:6): apparmor="DENIED" operation="change_onexec" info="label not found" error=-2 profile="unconfined" name="system_tor" pid=1691 comm="(tor)"
Jul 05 01:53:16 LSW systemd[1691]: tor@default.service: Failed at step APPARMOR spawning /usr/bin/tor: No such file or directory

One thing to try in the short term is putting app armor into warn mode for tor:

apt install apparmor-utils
aa-complain system_tor
systemctl restart tor

Thanks for your patience! Talk more soon.

[ghost]

@cpu yes putting app armor into warn mode solved the issue.
I reinstall the OS, install all prerequisites, install TOR, apparmor, and apparmor-utils trough APT, and then "aa-complain system_tor". After that I execute the ./streisand and voila!
Thanks for your kind assistance!

[cpu]

Hi @NanoG6,

Ok! I'm glad that workaround was helpful to you. That certainly confirms that there are remaining AppArmor issues to sort out.

When I can find the time I will see about provisioning a small LeaseWeb server to try and reproduce the problem on my own so that I can iterate on a solution. Was there anything "special" about your particular instance? Do you think a "S" virtual instance with 16.04 would be an approximate match to your affected server?

Thanks!

[ghost]

Yes that is my server package, the one with 1 core, 1 gb ram, 40 gb storage, and 4 tb bandwidth. The only different is mine using SAN instead of SSD (not sure wether it is SAN SSD or HDD), and a lot cheaper because it was promotional offer :)

[cpu]

@NanoG6 Great - thanks! I'm going to update this issue title to reflect the app armor problem and will hopefully have a fix in the next few days.

[cpu]

Linking this as another related issue to #778

[cpu]

I tried to sign up for a LeaseWeb account. Unfortunately they require some kind of manual telephone verification process for initial account creation that I find uncomfortable. Worse, they don't mention this requirement ahead of time & have already charged me $7 for an order that is "on hold" pending phone verification. Pretty un-enthused about that user experience :'(

At this point I'll have to reproduce the problem elsewhere & if I can't I'll have to close this issue as a peculiarity of an unsupported provider.

[ghost]

Yeah they did manual verification to me too.. In that case I believe that $7 would be refunded to you?
By the way I really want to give you access to my server, but my office colleague and friends already using this server for VPN connection :(

[cpu]

@NanoG6 That's ok - I'll try this on a few providers and see what I can come up with. I will probably ask you to test a few things on your leaseweb instance if that's OK but I won't need access myself.

[ghost]

Sure! Just tell me what to do. Glad to help

[cpu]

@NanoG6 Can you share the output of uname -a from the affected machine?

[cpu]

Additionally, do you happen to know what virtualization technology LeaseWeb uses? Are they KVM or LXC based?

[ghost]

root@LSW:~# hostnamectl status
Static hostname: LSW
Icon name: computer-vm
Chassis: vm
Machine ID: 7714cd48---1677b73db45719067a
Boot ID: 622d6b5d6---82b10c95d556d873bc
Virtualization: bochs
Operating System: Ubuntu 16.04.2 LTS
Kernel: Linux 4.4.0-83-generic
Architecture: x86-64

Bochs? Haven't heard that

[ghost]

Ah just got a reply from support, it is based on CloudStack

[cpu]

Kernel: Linux 4.4.0-83-generic
it is based on CloudStack

I'm totally unfamiliar with CloudStack, but I'm beginning to suspect that the apparmor error you are seeing matches this bug: https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1648143 that stems from a bug related to stacking apparmor profiles with containers.

I'm not sure which kernel update "solved" the problem based on that Ubuntu bug report, perhaps 4.8.0-49.52, the last listed?

Can you also share the output of:

sudo grep -qa container /proc/1/environ

and

/bin/running-in-container

[ghost]

grep -qa container /proc/1/environ

cat /proc/1/environ
HOME=/init=/sbin/initrecovery=TERM=linuxdrop_caps=BOOT_IMAGE=/vmlinuz-4.4.0-83-genericPATH=/sbin:/usr/sbin:/bin:/usr/binPWD=/rootmnt=/root

/bin/running-in-container
-su: /bin/running-in-container: No such file or directory

[cpu]

@NanoG6 Thanks. At this point my best theory is that this is related to the CloudStack environment and your Linux kernel version. I haven't been able to replicate this on any of the supported providers or any of the additional VPS providers I have access to that I test local/remote provisioning with.

I'm going to close this issue for now since you have a viable workaround through disabling apparmor. If another user on a different provider runs into this problem we can reopen and dig more but until then I think I have to cut my losses here. Apologies! I really wanted to solve this mystery for good!

[mludvig]

I have the same problem on Linux Mint 18.2 running on my laptop, no CloudStack involved.

audit: type=1400 audit(1505909353.244:22): apparmor="DENIED" operation="change_onexec" info="label not found" error=-2 profile="unconfined" name="system_tor" pid=12347 comm="(tor)"

The workaround with aa-complain worked but happy to help with debugging the root cause.

[cpu]

@mludvig What is the target OS / provider of the Streisand run? Can you share uname -a?

[mludvig]

Linux koumak 4.4.0-93-generic #116-Ubuntu SMP Fri Aug 11 21:17:51 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

Actually .. I'm not using Streisand, just a tor package from Linux Mint / Ubuntu repo and getting that AppArmor error. Not sure if it's any good as a bugreport. I was googling for the error message and landed here :)

[cpu]

@mludvig If you aren't using Streisand this won't be the right place to report that bug :-)