Multiple tasks getting assigned to the same machine

[Al33t]

My issue is:

When submitting tasks in rapid succession, two tasks can get assigned to the same machine, after which that vm becomes corrupt and needs to be restarted. This is usually only observed after a while, i.e. several have to be submitted and then after any length of time this may occur.

My Cuckoo version and operating system are:

Cuckoo version 2.0.7 Debian 10

This can be reproduced by:

Submitting several tasks in rapid succession. One wonders if there is another variable at play since the ease of reproducing this would make it obvious that most users would be affected by this but none of the other reported issues seemed comparable.

The issue has already been analyzed and a race condition was determined to be the cause. By instrumenting the code, a carefully placed delay, the issue got aggravated to such extent that it was observed sooner and more frequent.

The log, error, files etc can be found at:

2020-09-12 03:35:57,259 [cuckoo.core.scheduler] INFO: Task #68871: acquired machine 18 (label=18)
2020-09-12 03:35:57,262 [cuckoo.core.resultserver] DEBUG: Now tracking machine n.n.n.n for task #68871
2020-09-12 03:35:57,263 [cuckoo.core.plugins] DEBUG: Started auxiliary module: Replay
2020-09-12 03:35:57,263 [cuckoo.core.scheduler] INFO: Task #68874: acquired machine 18 (label=18)
2020-09-12 03:35:57,264 [cuckoo.core.resultserver] DEBUG: Now tracking machine n.n.n.n for task #68874
2020-09-12 03:35:57,312 [cuckoo.core.plugins] DEBUG: Started auxiliary module: Replay
2020-09-12 03:35:57,351 [cuckoo.auxiliary.sniffer] INFO: Started sniffer with PID 20509 (interface=vnet18, host=n.n.n.n)
2020-09-12 03:35:57,353 [cuckoo.core.plugins] DEBUG: Started auxiliary module: Sniffer
2020-09-12 03:35:57,389 [cuckoo.auxiliary.sniffer] INFO: Started sniffer with PID 20510 (interface=vnet18, host=n.n.n.n)
2020-09-12 03:35:57,408 [cuckoo.core.plugins] DEBUG: Started auxiliary module: Sniffer
2020-09-12 03:35:57,441 [cuckoo.machinery.qemu] DEBUG: Starting vm 18
2020-09-12 03:35:57,459 [cuckoo.machinery.qemu] DEBUG: Executing QEMU ['/home/cuckoo/qemu-5.1.0/x86_64-softmmu/qemu-system-x86_64', '-m', '4G', '-display', 'none', '-device', 'intel-hda', '-device', 'hda-duplex', '-cpu', 'Haswell-v4,-hyp
ervisor,kvm=off', '-smp', 'cpus=2,cores=2,threads=1', '-drive', 'file=/data/qemu_images/cuckoo_template_gzip18.qcow2,format=qcow2,cache=unsafe', '-vga', 'std', '-device', 'e1000,netdev=netw0,mac=XX:XX:XX:XX:XX:XX', '-netdev', 'bridge,id=
netw0,br=vnet18,helper=/home/cuckoo/qemu-5.1.0/qemu-bridge-helper', '-bios', '/home/cuckoo/seabios/out/bios.bin', '-loadvm', 'cuckoo', '-enable-kvm']
2020-09-12 03:35:57,502 [cuckoo.machinery.qemu] DEBUG: Starting vm 18
2020-09-12 03:35:57,510 [cuckoo.machinery.qemu] DEBUG: Executing QEMU ['/home/cuckoo/qemu-5.1.0/x86_64-softmmu/qemu-system-x86_64', '-m', '4G', '-display', 'none', '-device', 'intel-hda', '-device', 'hda-duplex', '-cpu', 'Haswell-v4,-hyp
ervisor,kvm=off', '-smp', 'cpus=2,cores=2,threads=1', '-drive', 'file=/data/qemu_images/cuckoo_template_gzip18.qcow2,format=qcow2,cache=unsafe', '-vga', 'std', '-device', 'e1000,netdev=netw0,mac=XX:XX:XX:XX:XX:XX', '-netdev', 'bridge,id=
netw0,br=vnet18,helper=/home/cuckoo/qemu-5.1.0/qemu-bridge-helper', '-bios', '/home/cuckoo/seabios/out/bios.bin', '-loadvm', 'cuckoo', '-enable-kvm']
2020-09-12 03:35:57,714 [cuckoo.core.guest] INFO: Starting analysis #68871 on guest (id=18, ip=n.n.n.n)
2020-09-12 03:35:57,769 [cuckoo.core.guest] INFO: Starting analysis #68874 on guest (id=18, ip=n.n.n.n)
...
2020-09-12 03:36:07,971 [cuckoo.core.guest] INFO: Guest is running Cuckoo Agent 0.10 (id=18, ip=n.n.n.n)
2020-09-12 03:36:07,973 [cuckoo.core.guest] INFO: Guest is running Cuckoo Agent 0.10 (id=18, ip=n.n.n.n)
...
2020-09-12 03:36:07,998 [cuckoo.core.guest] DEBUG: Uploading analyzer to guest (id=18, ip=n.n.n.n, monitor=latest, size=1836501)
...
2020-09-12 03:36:08,095 [cuckoo.machinery.qemu] DEBUG: Stopping vm 18
2020-09-12 03:36:08,111 [cuckoo.core.resultserver] DEBUG: Stopped tracking machine n.n.n.n for task #68871
...
2020-09-12 03:36:08,446 [cuckoo.core.scheduler] ERROR: Failure in AnalysisManager.run
Traceback (most recent call last):
  File "/home/cuckoo/cuckoo_venv/local/lib/python2.7/site-packages/cuckoo/core/scheduler.py", line 755, in run
    self.launch_analysis()
  File "/home/cuckoo/cuckoo_venv/local/lib/python2.7/site-packages/cuckoo/core/scheduler.py", line 541, in launch_analysis
    self.guest_manage(options)
  File "/home/cuckoo/cuckoo_venv/local/lib/python2.7/site-packages/cuckoo/core/scheduler.py", line 404, in guest_manage
    self.guest_manager.start_analysis(options, monitor)
  File "/home/cuckoo/cuckoo_venv/local/lib/python2.7/site-packages/cuckoo/core/guest.py", line 488, in start_analysis
    self.get("/pinning")
  File "/home/cuckoo/cuckoo_venv/local/lib/python2.7/site-packages/cuckoo/core/guest.py", line 320, in get
    do_raise and r.raise_for_status()
  File "/home/cuckoo/cuckoo_venv/local/lib/python2.7/site-packages/requests/models.py", line 909, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
HTTPError: 500 Server Error: Internal Server Error for url: http://n.n.n.n:8000/pinning

[nadir3392]

hi, this issue it's happen after addition the guest Linux, actually i don't have the solution. thank's

[Al33t]

I think I do, see #3106.

[cccs-kevin]

Thanks for your work @Al33t , I'm also having this issue in my production system. Will implement your suggested PR and test.

[cccs-kevin]

Confirmed, PR is the solution.

[nadir3392]

@cccs-kevin how did you solve this problem. thank you.

[cccs-kevin]

@nadir3392 Make the code change from the following PR: https://github.com/cuckoosandbox/cuckoo/pull/3106 and restart the Cuckoo Daemon for the changes in database.py to take effect.