How to debug

Collect debug files

An Ansible playbook is available in order to gather logs and other useful files.

The playbook is ansible/playbooks/collect_debug.yml and it will allow you to retrieve on each host:

  • IRMA Files (located on the multiples hosts);
  • Systemd logs;
  • Application logs (Nginx, RabbitMQ, PostgreSQL).

After running the playbook, all the files are available in the directory specified in the debug_directory variable of the playbook. The files are store in directories named after the host they where retrieve from (<debug_directory>/<host_name>/<debug_files_or_directory>). Most of the files are plain text but Systemd logs are using a binary format. To explore and read them, you’ll need the journalctl command, for example:

$ journalctl -D debug/brain.irma/var/log/journal

Switch debug log on

Configuration file for frontend, brain and probe is located by default in the config folder and is named respectively frontend.ini, brain.ini and probe.ini.

To turn on debug log just add the following line:

 [log]
 syslog = 0
 debug = 1

and restart all related applications.

To turn on SQL debug log (warning: its verbose) just add the following line:

 [log]
 syslog = 0
 debug = 1
 sql_debug = 1

and restart all related applications.

Debug a probe

Open a session on the probe machine and change directory to the irma-probe location. Try the run_module tool on a file to see what analyzer is detected and what is its output on a file.

 $ sudo su deploy
 $ cd /opt/irma/irma-probe/current
 $ ./venv/bin/python -m extras.tools.run_module

 [...]
 usage: run_module.py [-h] [-v]
                  {Unarchive,StaticAnalyzer,ClamAV,VirusTotal} filename
                  [filename ...]
 run_module.py: error: too few arguments

Here 4 probes are automatically detected. Now try one on a file:

$ ./venv/bin/python -m extras.tools.run_module ClamAV requirements.txt
{'database': {'/var/lib/clamav/bytecode.cvd': {'ctime': 1458640823.285298,
                                           'mtime': 1458640823.069295,
                                           'sha256': '82972e6cc5f1204829dba913cb1a0b5f8152eb73d3407f6b86cf388626cff1a1'},
          '/var/lib/clamav/daily.cvd': {'ctime': 1458640822.8932924,
                                        'mtime': 1458640822.6692889,
                                        'sha256': '9804c9b9aaf983f85b4f13a7053f98eb7cca5a5a88d3897d49b22182b228885f'},
          '/var/lib/clamav/main.cvd': {'ctime': 1458640821.6972747,
                                       'mtime': 1458640813.9771628,
                                       'sha256': '4a8dfbc4c44704186ad29b5a3f8bdb6674b679cecdf83b156dd1c650129b56f2'}},
 'duration': 0.0045299530029296875,
 'error': None,
 'name': 'Clam AntiVirus Scanner',
 'platform': 'linux2',
 'results': None,
 'status': 0,
 'type': 'antivirus',
 'version': '0.99'}

And check the output.

Debug Ansible Provisioning

To debug errors while provisioning (same goes with deployment) with following typical command:

$ ansible-playbook  --private-key=~/.vagrant.d/insecure_private_key --inventory-file=.vagrant/provisioners/ansible/inventory/vagrant_ansible_inventory -u vagrant playbooks/provisioning.yml

Example output:

TASK [Mayeu.RabbitMQ : add rabbitmq user and set privileges] *******************
[DEPRECATION WARNING]: Using bare variables is deprecated. Update your playbooks so that the environment value uses the
full variable syntax ('{{rabbitmq_users_definitions}}').
This feature will be removed in a future release. Deprecation
warnings can be disabled by setting deprecation_warnings=False in ansible.cfg.
failed: [brain.irma] (item={u'vhost': u'mqbrain', u'password': u'brain', u'user': u'brain'}) => {"failed": true, "item": {"password": "brain", "user": "brain", "vhost": "mqbrain"}, "module_stderr": "", "module_stdout": "Traceback (most recent call last):\r\n  File \"/tmp/ansible_wKXoO5/ansible_module_rabbitmq_user.py\", line 302, in <module>\r\n    main()\r\n  File \"/tmp/ansible_wKXoO5/ansible_module_rabbitmq_user.py\", line 274, in main\r\n    if rabbitmq_user.get():\r\n  File \"/tmp/ansible_wKXoO5/ansible_module_rabbitmq_user.py\", line 155, in get\r\n    users = self._exec(['list_users'], True)\r\n  File \"/tmp/ansible_wKXoO5/ansible_module_rabbitmq_user.py\", line 150, in _exec\r\n    rc, out, err = self.module.run_command(cmd + args, check_rc=True)\r\n  File \"/tmp/ansible_wKXoO5/ansible_modlib.zip/ansible/module_utils/basic.py\", line 1993, in run_command\r\n  File \"/usr/lib/python2.7/posixpath.py\", line 261, in expanduser\r\n    if not path.startswith('~'):\r\nAttributeError: 'list' object has no attribute 'startswith'\r\n", "msg": "MODULE FAILURE", "parsed": false}

You could first increase ansible verbosity by adding -vvv option (-vvvv on windows for winrm debug), it will help is the problem is linked to arguments.

 $ ansible-playbook -vvv --private-key=~/.vagrant.d/insecure_private_key --inventory-file=.vagrant/provisioners/ansible/inventory/vagrant_ansible_inventory -u vagrant playbooks/provisioning.yml
 TASK [Mayeu.RabbitMQ : add rabbitmq user and set privileges] *******************
 task path: /home/alex/repo/irma-ansible/roles/Mayeu.RabbitMQ/tasks/vhost.yml:13
 [DEPRECATION WARNING]: Using bare variables is deprecated. Update your playbooks so that the environment value uses the full
 variable syntax ('{{rabbitmq_users_definitions}}').
 This feature will be removed in a future release. Deprecation warnings can be
 disabled by setting deprecation_warnings=False in ansible.cfg.
 <127.0.0.1> ESTABLISH SSH CONNECTION FOR USER: vagrant
 <127.0.0.1> SSH: EXEC ssh -C -q -o ForwardAgent=yes -o Port=2222 -o 'IdentityFile="/home/alex/.vagrant.d/insecure_private_key"' -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o User=vagrant -o ConnectTimeout=10 127.0.0.1 '/bin/sh -c '"'"'( umask 77 && mkdir -p "` echo $HOME/.ansible/tmp/ansible-tmp-1468570550.09-211613386938202 `" && echo ansible-tmp-1468570550.09-211613386938202="` echo $HOME/.ansible/tmp/ansible-tmp-1468570550.09-211613386938202 `" ) && sleep 0'"'"''
 <127.0.0.1> PUT /tmp/tmpiysJ6l TO /home/vagrant/.ansible/tmp/ansible-tmp-1468570550.09-211613386938202/rabbitmq_user
 <127.0.0.1> SSH: EXEC sftp -b - -C -o ForwardAgent=yes -o Port=2222 -o 'IdentityFile="/home/alex/.vagrant.d/insecure_private_key"' -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o User=vagrant -o ConnectTimeout=10 '[127.0.0.1]'
 <127.0.0.1> ESTABLISH SSH CONNECTION FOR USER: vagrant
 <127.0.0.1> SSH: EXEC ssh -C -q -o ForwardAgent=yes -o Port=2222 -o 'IdentityFile="/home/alex/.vagrant.d/insecure_private_key"' -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o User=vagrant -o ConnectTimeout=10 -tt 127.0.0.1 '/bin/sh -c '"'"'sudo -H -S -n -u root /bin/sh -c '"'"'"'"'"'"'"'"'echo BECOME-SUCCESS-rbeeckncuxenewcwkayivqiwvarchlrd; LANG=fr_FR.UTF-8 LC_ALL=fr_FR.UTF-8 LC_MESSAGES=fr_FR.UTF-8 /usr/bin/python /home/vagrant/.ansible/tmp/ansible-tmp-1468570550.09-211613386938202/rabbitmq_user; rm -rf "/home/vagrant/.ansible/tmp/ansible-tmp-1468570550.09-211613386938202/" > /dev/null 2>&1'"'"'"'"'"'"'"'"' && sleep 0'"'"''
 failed: [brain.irma] (item={u'vhost': u'mqbrain', u'password': u'brain', u'user': u'brain'}) => {"failed": true, "invocation": {"module_name": "rabbitmq_user"}, "item": {"password": "brain", "user": "brain", "vhost": "mqbrain"}, "module_stderr": "", "module_stdout": "Traceback (most recent call last):\r\n  File \"/tmp/ansible_Qo3lZl/ansible_module_rabbitmq_user.py\", line 302, in <module>\r\n    main()\r\n  File \"/tmp/ansible_Qo3lZl/ansible_module_rabbitmq_user.py\", line 274, in main\r\n    if rabbitmq_user.get():\r\n  File \"/tmp/ansible_Qo3lZl/ansible_module_rabbitmq_user.py\", line 155, in get\r\n    users = self._exec(['list_users'], True)\r\n  File \"/tmp/ansible_Qo3lZl/ansible_module_rabbitmq_user.py\", line 150, in _exec\r\n    rc, out, err = self.module.run_command(cmd + args, check_rc=True)\r\n  File \"/tmp/ansible_Qo3lZl/ansible_modlib.zip/ansible/module_utils/basic.py\", line 1993, in run_command\r\n  File \"/usr/lib/python2.7/posixpath.py\", line 261, in expanduser\r\n    if not path.startswith('~'):\r\nAttributeError: 'list' object has no attribute 'startswith'\r\n", "msg": "MODULE FAILURE", "parsed": false}

In this particular case, verbose doesn’t add much information as the problem is linked to ansible scripts. Let’s go one level deeper so. Ansible output the temporary script executed on guest (highlighted in previous code block) but delete it just after execution. To further debug it we will set ansible to keep remote files and the debug session will now takes place inside the guest.

$ ANSIBLE_KEEP_REMOTE_FILES=1 ansible-playbook -vvv --private-key=~/.vagrant.d/insecure_private_key --inventory-file=.vagrant/provisioners/ansible/inventory/vagrant_ansible_inventory -u vagrant playbooks/provisioning.yml

in debug log get the temporary ansible path to remote script:

/usr/bin/python /home/vagrant/.ansible/tmp/ansible-tmp-1468571039.87-134696488633275/rabbitmq_user

Log in to remote machine and go to the temporary ansible dir. Explode the compressed script and run it locallly:

$ vagrant@brain:~/.ansible/tmp/ansible-tmp-1468571039.87-134696488633275$ ls
rabbitmq_user

$ vagrant@brain:~/.ansible/tmp/ansible-tmp-1468571039.87-134696488633275$ python rabbitmq_user explode
Module expanded into:
/home/vagrant/.ansible/tmp/ansible-tmp-1468571039.87-134696488633275/debug_dir

$ vagrant@brain:~/.ansible/tmp/ansible-tmp-1468571039.87-134696488633275$ ls debug_dir/
ansible
ansible_module_rabbitmq_user.py
args

$ vagrant@brain:~/.ansible/tmp/ansible-tmp-1468571039.87-134696488633275$ python rabbitmq_user execute
Traceback (most recent call last):
  File "/home/vagrant/.ansible/tmp/ansible-tmp-1468571039.87-134696488633275/debug_dir/ansible_module_rabbitmq_user.py", line 302, in <module>
    main()
  File "/home/vagrant/.ansible/tmp/ansible-tmp-1468571039.87-134696488633275/debug_dir/ansible_module_rabbitmq_user.py", line 274, in main
   if rabbitmq_user.get():
  File "/home/vagrant/.ansible/tmp/ansible-tmp-1468571039.87-134696488633275/debug_dir/ansible_module_rabbitmq_user.py", line 155, in get
    users = self._exec(['list_users'], True)
  File "/home/vagrant/.ansible/tmp/ansible-tmp-1468571039.87-134696488633275/debug_dir/ansible_module_rabbitmq_user.py", line 150, in _exec
    rc, out, err = self.module.run_command(cmd + args, check_rc=True)
  File "/home/vagrant/.ansible/tmp/ansible-tmp-1468571039.87-134696488633275/debug_dir/ansible/module_utils/basic.py", line 1993, in run_command
    args = [ os.path.expandvars(os.path.expanduser(x)) for x in args if x is not None ]
  File "/usr/lib/python2.7/posixpath.py", line 261, in expanduser
    if not path.startswith('~'):
AttributeError: 'list' object has no attribute 'startswith'

You could now add debug to source files and properly understand where the problem is. In our example case, it is an ansible problem related to module_rabbitmq_user present in 2.1.0.0 see github PR