Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Scanning cannot be completed correctly. #196

Closed
gitsang opened this issue Feb 29, 2024 · 20 comments
Closed

Scanning cannot be completed correctly. #196

gitsang opened this issue Feb 29, 2024 · 20 comments
Assignees
Labels
can't reproduce We were not able to reproduce the issue with the provided information EMBArk

Comments

@gitsang
Copy link

gitsang commented Feb 29, 2024

Describe the bug

Scanning has finished, but the page is still running. The progress froze and no longer updates.

Larger firmware will trigger this bug more easily.

To Reproduce
Steps to reproduce the behavior:

  1. EMBArk installation (default mode/docker-mode)
  2. Start EMBArk: sudo ./run-server.sh
  3. Use the firmware available here:
  4. Analyze firmware and waiting for finished
  5. Scanning has finished, but the page is still running.

Expected behavior

Scanning end and show reports。

Screenshots

image
image
image

logreader.log incomplete

$ tail -f -n10 /var/www/emba_logs/ac93bbfe-2d8c-4530-8ba2-8c2cb0320519/logreader.log
[*] Tue Jan 30 19:58:24 UTC 2024 - S107_deep_password_search finished
[*] Tue Jan 30 19:58:27 UTC 2024 - S118_busybox_verifier starting
[*] Tue Jan 30 20:10:20 UTC 2024 - S118_busybox_verifier finished
[*] Tue Jan 30 21:18:10 UTC 2024 - S109_jtr_local_pw_cracking finished
[*] Wed Jan 31 01:13:53 UTC 2024 - S24_kernel_bin_identifier finished
[*] Wed Jan 31 01:24:32 UTC 2024 - S25_kernel_check finished
[*] Wed Jan 31 05:02:07 UTC 2024 - S115_usermode_emulator finished
[*] Wed Jan 31 05:13:19 UTC 2024 - S116_qemu_version_detection finished
[*] Wed Jan 31 05:38:10 UTC 2024 - S35_http_file_check finished
[*] Wed Jan 31 06:05:55 UTC 2024 - S26_kernel_vuln_verifier finished

while emba_logs/emba.log is complete

$ tail -f -n25 /var/www/emba_logs/ac93bbfe-2d8c-4530-8ba2-8c2cb0320519/emba_logs/emba.log
[*] Wed Jan 31 01:24:32 UTC 2024 - S25_kernel_check finished
[*] Wed Jan 31 05:02:07 UTC 2024 - S115_usermode_emulator finished
[*] Wed Jan 31 05:13:19 UTC 2024 - S116_qemu_version_detection finished
[*] Wed Jan 31 05:38:10 UTC 2024 - S35_http_file_check finished
[*] Wed Jan 31 06:05:55 UTC 2024 - S26_kernel_vuln_verifier finished
[*] Wed Jan 31 15:28:36 UTC 2024 - S09_firmware_base_version_check finished
[*] Thu Feb  1 17:14:50 UTC 2024 - S14_weak_func_radare_check finished
[!] Testing phase ended on Thu Feb  1 17:14:50 UTC 2024 and took about 2 days and 08:53:18

[!] Reporting phase started on Thu Feb  1 17:14:50 UTC 2024

[*] Thu Feb  1 17:14:51 UTC 2024 - F05_qs_resolver starting
[*] Thu Feb  1 17:14:51 UTC 2024 - F05_qs_resolver finished
[*] Thu Feb  1 17:14:51 UTC 2024 - F10_license_summary starting
[*] Thu Feb  1 17:15:19 UTC 2024 - F10_license_summary finished
[*] Thu Feb  1 17:15:19 UTC 2024 - F20_vul_aggregator starting
[*] Thu Feb  1 20:01:40 UTC 2024 - F20_vul_aggregator finished
[*] Thu Feb  1 20:01:40 UTC 2024 - F21_cyclonedx_sbom starting
[*] Thu Feb  1 20:01:45 UTC 2024 - F21_cyclonedx_sbom finished
[*] Thu Feb  1 20:01:46 UTC 2024 - F50_base_aggregator starting
[*] Thu Feb  1 20:02:28 UTC 2024 - F50_base_aggregator finished
[!] Test ended on Thu Feb  1 20:02:28 UTC 2024 and took about 2 days and 11:40:56

[*] Open the web-report with firefox /var/www/emba_logs/ac93bbfe-2d8c-4530-8ba2-8c2cb0320519/emba_logs/html-report/index.html

Desktop (please complete the following information):

  • OS: Ubuntu20.04

Additional context

Now I can export report from /var/www/emba_logs/ac93bbfe-2d8c-4530-8ba2-8c2cb0320519/emba_logs/html-report/index.html, but that's not a long-term solution.

Copy link

Thank you for contributing an issue!

Welcome to the EMBA firmware analysis community!

We are glad you are here and appreciate your contribution. Please keep in mind our contributing guidelines here and here.
Also, please check existing open issues and consider to open a discussion in the dedicated discussion area.
Additionally, we have collected a lot of details around EMBArk, the installation and the usage of EMBArk in our Wiki.

If you like EMBA you have the chance to support us by becoming a Sponsor or buying some beer here.

This is an automatic message. Allow for time for the EMBA community to be able to read the issue and comment on it.

@BenediktMKuehne
Copy link
Member

Is there a firmware we can use to reproduce the issue?

@gitsang
Copy link
Author

gitsang commented Feb 29, 2024

Is there a firmware we can use to reproduce the issue?

Sorry, our firmware involves company secrets and cannot be provided to you. I am trying to scan some open-source firmware to reproduce this issue. If reproduced, I will provide it to you.

Before that maybe you can try using larger firmware first (according to discussions within our team, this bug are more likely to occur with firmware over 2GB).

@m-1-k-3 m-1-k-3 added the EMBArk label Feb 29, 2024
@BenediktMKuehne BenediktMKuehne added the can't reproduce We were not able to reproduce the issue with the provided information label Feb 29, 2024
@BenediktMKuehne
Copy link
Member

I'll make some tests on larger FW-files, but so far I'm unable to reproduce the issue

@torabi12
Copy link

torabi12 commented Mar 2, 2024

Something is not OK with large FW scans in EMBArk.
I am testing the .ext4 file what I have sent to Mike a few days before and the scan has been hanging at 46% since 1 day ago.

image

In the console also some error messages:

image

I am going to wait till monday morning, but even if the test runs, it is likely that the results will not be available under EMBArk.

@gitsang
Copy link
Author

gitsang commented Mar 4, 2024

I have reproduced it through the public binary file.

image

  • web log is complete

image

  • logreader.log was stuck at S22_php_check finished
`logreader.log`
ubuntu@embark:/var/www/emba_logs/56137802-4901-4312-9362-4d00bd375624$ cat logreader.log
[*] Quest container d6498f5507c77a8e13a81d402dafedc78feca6eeec26389ea5970d23294e110e started and detached.

[!] Pre-checking phase started on Fri Mar  1 07:43:20 UTC 2024
    Firmware binary path: /firmware
[*] Fri Mar  1 07:43:20 UTC 2024 - P02_firmware_bin_file_check starting
[*] Quest container done
[*] Fri Mar  1 07:44:50 UTC 2024 - P02_firmware_bin_file_check finished
[*] Fri Mar  1 07:44:50 UTC 2024 - P05_patools_init starting
[*] Fri Mar  1 07:44:52 UTC 2024 - P05_patools_init finished
[*] Fri Mar  1 07:44:52 UTC 2024 - P35_uefi_extractor starting
[*] Fri Mar  1 08:08:11 UTC 2024 - P35_UEFI_extractor finished
[*] Fri Mar  1 08:08:11 UTC 2024 - P55_unblob_extractor starting
[*] Fri Mar  1 08:08:12 UTC 2024 - P55_unblob_extractor finished
[*] Fri Mar  1 08:08:12 UTC 2024 - P60_deep_extractor starting
[*] Fri Mar  1 08:08:12 UTC 2024 - P60_deep_extractor finished
[*] Fri Mar  1 08:08:12 UTC 2024 - P61_binwalk_extractor starting
[*] Fri Mar  1 08:08:12 UTC 2024 - P61_binwalk_extractor finished
[*] Fri Mar  1 08:08:13 UTC 2024 - P65_package_extractor starting
[*] Fri Mar  1 08:43:42 UTC 2024 - P65_package_extractor finished
[*] Fri Mar  1 08:43:42 UTC 2024 - P99_prepare_analyzer starting
[*] Fri Mar  1 09:53:51 UTC 2024 - P99_prepare_analyzer finished
[!] Pre-checking phase ended on Fri Mar  1 09:53:51 UTC 2024 and took about 0 days and 02:10:37

[!] Testing phase started on Fri Mar  1 09:53:51 UTC 2024
    Firmware path: /logs/firmware
[*] Fri Mar  1 09:53:52 UTC 2024 - S12_binary_protection starting
[*] Fri Mar  1 09:53:52 UTC 2024 - S09_firmware_base_version_check starting
[*] Fri Mar  1 09:53:52 UTC 2024 - S02_uefi_fwhunt starting
[*] Fri Mar  1 09:53:52 UTC 2024 - S03_firmware_bin_base_analyzer starting
[*] Fri Mar  1 09:53:52 UTC 2024 - S05_firmware_details starting
[*] Fri Mar  1 09:53:52 UTC 2024 - S06_distribution_identification starting
[*] Fri Mar  1 09:53:52 UTC 2024 - S07_bootloader_check starting
[*] Fri Mar  1 09:53:52 UTC 2024 - S10_binaries_basic_check not executed - blacklist triggered
[*] Fri Mar  1 09:53:52 UTC 2024 - S08_package_mgmt_extractor starting
[*] Fri Mar  1 09:53:52 UTC 2024 - S13_weak_func_check starting
[*] Fri Mar  1 09:53:52 UTC 2024 - S02_UEFI_FwHunt finished
[*] Fri Mar  1 09:53:53 UTC 2024 - S15_radare_decompile_checks not executed - blacklist triggered
[*] Fri Mar  1 09:53:53 UTC 2024 - S14_weak_func_radare_check starting
[*] Fri Mar  1 09:53:53 UTC 2024 - S19_apk_check starting
[*] Fri Mar  1 09:53:53 UTC 2024 - S20_shell_check starting
[*] Fri Mar  1 09:53:53 UTC 2024 - S21_python_check starting
[*] Fri Mar  1 09:53:53 UTC 2024 - S22_php_check starting
[*] Fri Mar  1 09:53:53 UTC 2024 - S23_lua_check starting
[*] Fri Mar  1 09:53:53 UTC 2024 - S24_kernel_bin_identifier starting
[*] Fri Mar  1 09:53:53 UTC 2024 - S25_kernel_check starting
[*] Fri Mar  1 09:53:53 UTC 2024 - S26_kernel_vuln_verifier starting
[*] Fri Mar  1 09:53:53 UTC 2024 - S35_http_file_check starting
[*] Fri Mar  1 09:53:53 UTC 2024 - S36_lighttpd starting
[*] Fri Mar  1 09:53:54 UTC 2024 - S40_weak_perm_check starting
[*] Fri Mar  1 09:53:54 UTC 2024 - S45_pass_file_check starting
[*] Fri Mar  1 09:53:54 UTC 2024 - S50_authentication_check starting
[*] Fri Mar  1 09:53:54 UTC 2024 - S55_history_file_check starting
[*] Fri Mar  1 09:53:54 UTC 2024 - S60_cert_file_check starting
[*] Fri Mar  1 09:53:54 UTC 2024 - S65_config_file_check starting
[*] Fri Mar  1 09:53:54 UTC 2024 - S75_network_check starting
[*] Fri Mar  1 09:53:54 UTC 2024 - S21_python_check finished
[*] Fri Mar  1 09:53:54 UTC 2024 - S80_cronjob_check starting
[*] Fri Mar  1 09:53:54 UTC 2024 - S85_ssh_check starting
[*] Fri Mar  1 09:53:54 UTC 2024 - S90_mail_check starting
[*] Fri Mar  1 09:53:54 UTC 2024 - S99_grepit not executed - blacklist triggered
[*] Fri Mar  1 09:53:54 UTC 2024 - S95_interesting_files_check starting
[*] Fri Mar  1 09:53:55 UTC 2024 - S100_command_inj_check starting
[*] Fri Mar  1 09:53:55 UTC 2024 - S106_deep_key_search starting
[*] Fri Mar  1 09:53:55 UTC 2024 - S08_package_mgmt_extractor finished
[*] Fri Mar  1 09:53:55 UTC 2024 - S107_deep_password_search starting
[*] Fri Mar  1 09:53:56 UTC 2024 - S36_lighttpd finished
[*] Fri Mar  1 09:53:56 UTC 2024 - S90_mail_check finished
[*] Fri Mar  1 09:53:56 UTC 2024 - S80_cronjob_check finished
[*] Fri Mar  1 09:53:56 UTC 2024 - S108_stacs_password_search starting
[*] Fri Mar  1 09:53:56 UTC 2024 - S109_jtr_local_pw_cracking starting
[*] Fri Mar  1 09:53:57 UTC 2024 - S110_yara_check not executed - blacklist triggered
[*] Fri Mar  1 09:53:57 UTC 2024 - S115_usermode_emulator starting
[*] Fri Mar  1 09:53:57 UTC 2024 - S40_weak_perm_check finished
[*] Fri Mar  1 09:53:58 UTC 2024 - S116_qemu_version_detection starting
[*] Fri Mar  1 09:53:58 UTC 2024 - S100_command_inj_check finished
[*] Fri Mar  1 09:53:58 UTC 2024 - S118_busybox_verifier starting
[*] Fri Mar  1 09:53:59 UTC 2024 - S75_network_check finished
[*] Fri Mar  1 09:53:59 UTC 2024 - S55_history_file_check finished
[*] Fri Mar  1 09:54:14 UTC 2024 - S85_ssh_check finished
[*] Fri Mar  1 09:54:18 UTC 2024 - S07_bootloader_check finished
[*] Fri Mar  1 09:54:20 UTC 2024 - S06_distribution_identification finished
[*] Fri Mar  1 09:54:23 UTC 2024 - S95_interesting_files_check finished
[*] Fri Mar  1 09:54:33 UTC 2024 - S60_cert_file_check finished
[*] Fri Mar  1 09:54:37 UTC 2024 - S50_authentication_check finished
[*] Fri Mar  1 09:54:39 UTC 2024 - S65_config_file_check finished
[*] Fri Mar  1 09:55:11 UTC 2024 - S106_deep_key_search finished
[*] Fri Mar  1 09:55:20 UTC 2024 - S05_firmware_details finished
[*] Fri Mar  1 09:56:15 UTC 2024 - S22_php_check finished
  • emba_logs/emba.log is complete.
`emba_logs/emba.log`
ubuntu@embark:/var/www/emba_logs/56137802-4901-4312-9362-4d00bd375624$ cat emba_logs/emba.log
[*] Quest container d6498f5507c77a8e13a81d402dafedc78feca6eeec26389ea5970d23294e110e started and detached.

[!] Pre-checking phase started on Fri Mar  1 07:43:20 UTC 2024
    Firmware binary path: /firmware
[*] Fri Mar  1 07:43:20 UTC 2024 - P02_firmware_bin_file_check starting
[*] Quest container done
[*] Fri Mar  1 07:44:50 UTC 2024 - P02_firmware_bin_file_check finished
[*] Fri Mar  1 07:44:50 UTC 2024 - P05_patools_init starting
[*] Fri Mar  1 07:44:52 UTC 2024 - P05_patools_init finished
[*] Fri Mar  1 07:44:52 UTC 2024 - P35_uefi_extractor starting
[*] Fri Mar  1 08:08:11 UTC 2024 - P35_UEFI_extractor finished
[*] Fri Mar  1 08:08:11 UTC 2024 - P55_unblob_extractor starting
[*] Fri Mar  1 08:08:12 UTC 2024 - P55_unblob_extractor finished
[*] Fri Mar  1 08:08:12 UTC 2024 - P60_deep_extractor starting
[*] Fri Mar  1 08:08:12 UTC 2024 - P60_deep_extractor finished
[*] Fri Mar  1 08:08:12 UTC 2024 - P61_binwalk_extractor starting
[*] Fri Mar  1 08:08:12 UTC 2024 - P61_binwalk_extractor finished
[*] Fri Mar  1 08:08:13 UTC 2024 - P65_package_extractor starting
[*] Fri Mar  1 08:43:42 UTC 2024 - P65_package_extractor finished
[*] Fri Mar  1 08:43:42 UTC 2024 - P99_prepare_analyzer starting
[*] Fri Mar  1 09:53:51 UTC 2024 - P99_prepare_analyzer finished
[!] Pre-checking phase ended on Fri Mar  1 09:53:51 UTC 2024 and took about 0 days and 02:10:37

[!] Testing phase started on Fri Mar  1 09:53:51 UTC 2024
    Firmware path: /logs/firmware
[*] Fri Mar  1 09:53:52 UTC 2024 - S12_binary_protection starting
[*] Fri Mar  1 09:53:52 UTC 2024 - S09_firmware_base_version_check starting
[*] Fri Mar  1 09:53:52 UTC 2024 - S02_uefi_fwhunt starting
[*] Fri Mar  1 09:53:52 UTC 2024 - S03_firmware_bin_base_analyzer starting
[*] Fri Mar  1 09:53:52 UTC 2024 - S05_firmware_details starting
[*] Fri Mar  1 09:53:52 UTC 2024 - S06_distribution_identification starting
[*] Fri Mar  1 09:53:52 UTC 2024 - S07_bootloader_check starting
[*] Fri Mar  1 09:53:52 UTC 2024 - S10_binaries_basic_check not executed - blacklist triggered
[*] Fri Mar  1 09:53:52 UTC 2024 - S08_package_mgmt_extractor starting
[*] Fri Mar  1 09:53:52 UTC 2024 - S13_weak_func_check starting
[*] Fri Mar  1 09:53:52 UTC 2024 - S02_UEFI_FwHunt finished
[*] Fri Mar  1 09:53:53 UTC 2024 - S15_radare_decompile_checks not executed - blacklist triggered
[*] Fri Mar  1 09:53:53 UTC 2024 - S14_weak_func_radare_check starting
[*] Fri Mar  1 09:53:53 UTC 2024 - S19_apk_check starting
[*] Fri Mar  1 09:53:53 UTC 2024 - S20_shell_check starting
[*] Fri Mar  1 09:53:53 UTC 2024 - S21_python_check starting
[*] Fri Mar  1 09:53:53 UTC 2024 - S22_php_check starting
[*] Fri Mar  1 09:53:53 UTC 2024 - S23_lua_check starting
[*] Fri Mar  1 09:53:53 UTC 2024 - S24_kernel_bin_identifier starting
[*] Fri Mar  1 09:53:53 UTC 2024 - S25_kernel_check starting
[*] Fri Mar  1 09:53:53 UTC 2024 - S26_kernel_vuln_verifier starting
[*] Fri Mar  1 09:53:53 UTC 2024 - S35_http_file_check starting
[*] Fri Mar  1 09:53:53 UTC 2024 - S36_lighttpd starting
[*] Fri Mar  1 09:53:54 UTC 2024 - S40_weak_perm_check starting
[*] Fri Mar  1 09:53:54 UTC 2024 - S45_pass_file_check starting
[*] Fri Mar  1 09:53:54 UTC 2024 - S50_authentication_check starting
[*] Fri Mar  1 09:53:54 UTC 2024 - S55_history_file_check starting
[*] Fri Mar  1 09:53:54 UTC 2024 - S60_cert_file_check starting
[*] Fri Mar  1 09:53:54 UTC 2024 - S65_config_file_check starting
[*] Fri Mar  1 09:53:54 UTC 2024 - S75_network_check starting
[*] Fri Mar  1 09:53:54 UTC 2024 - S21_python_check finished
[*] Fri Mar  1 09:53:54 UTC 2024 - S80_cronjob_check starting
[*] Fri Mar  1 09:53:54 UTC 2024 - S85_ssh_check starting
[*] Fri Mar  1 09:53:54 UTC 2024 - S90_mail_check starting
[*] Fri Mar  1 09:53:54 UTC 2024 - S99_grepit not executed - blacklist triggered
[*] Fri Mar  1 09:53:54 UTC 2024 - S95_interesting_files_check starting
[*] Fri Mar  1 09:53:55 UTC 2024 - S100_command_inj_check starting
[*] Fri Mar  1 09:53:55 UTC 2024 - S106_deep_key_search starting
[*] Fri Mar  1 09:53:55 UTC 2024 - S08_package_mgmt_extractor finished
[*] Fri Mar  1 09:53:55 UTC 2024 - S107_deep_password_search starting
[*] Fri Mar  1 09:53:56 UTC 2024 - S36_lighttpd finished
[*] Fri Mar  1 09:53:56 UTC 2024 - S90_mail_check finished
[*] Fri Mar  1 09:53:56 UTC 2024 - S80_cronjob_check finished
[*] Fri Mar  1 09:53:56 UTC 2024 - S108_stacs_password_search starting
[*] Fri Mar  1 09:53:56 UTC 2024 - S109_jtr_local_pw_cracking starting
[*] Fri Mar  1 09:53:57 UTC 2024 - S110_yara_check not executed - blacklist triggered
[*] Fri Mar  1 09:53:57 UTC 2024 - S115_usermode_emulator starting
[*] Fri Mar  1 09:53:57 UTC 2024 - S40_weak_perm_check finished
[*] Fri Mar  1 09:53:58 UTC 2024 - S116_qemu_version_detection starting
[*] Fri Mar  1 09:53:58 UTC 2024 - S100_command_inj_check finished
[*] Fri Mar  1 09:53:58 UTC 2024 - S118_busybox_verifier starting
[*] Fri Mar  1 09:53:59 UTC 2024 - S75_network_check finished
[*] Fri Mar  1 09:53:59 UTC 2024 - S55_history_file_check finished
[*] Fri Mar  1 09:54:14 UTC 2024 - S85_ssh_check finished
[*] Fri Mar  1 09:54:18 UTC 2024 - S07_bootloader_check finished
[*] Fri Mar  1 09:54:20 UTC 2024 - S06_distribution_identification finished
[*] Fri Mar  1 09:54:23 UTC 2024 - S95_interesting_files_check finished
[*] Fri Mar  1 09:54:33 UTC 2024 - S60_cert_file_check finished
[*] Fri Mar  1 09:54:37 UTC 2024 - S50_authentication_check finished
[*] Fri Mar  1 09:54:39 UTC 2024 - S65_config_file_check finished
[*] Fri Mar  1 09:55:11 UTC 2024 - S106_deep_key_search finished
[*] Fri Mar  1 09:55:20 UTC 2024 - S05_firmware_details finished
[*] Fri Mar  1 09:56:15 UTC 2024 - S22_php_check finished
[*] Fri Mar  1 11:34:16 UTC 2024 - S118_busybox_verifier finished
[*] Fri Mar  1 13:33:50 UTC 2024 - S108_stacs_password_search finished
[*] Fri Mar  1 15:31:07 UTC 2024 - S45_pass_file_check finished
[*] Sat Mar  2 16:58:16 UTC 2024 - S12_binary_protection finished
[*] Sat Mar  2 20:51:03 UTC 2024 - S23_lua_check finished
[*] Sat Mar  2 23:30:57 UTC 2024 - S03_firmware_bin_base_analyzer finished
[*] Sun Mar  3 00:18:48 UTC 2024 - S107_deep_password_search finished
[*] Sun Mar  3 00:19:28 UTC 2024 - S109_jtr_local_pw_cracking finished
[*] Sun Mar  3 00:19:57 UTC 2024 - S13_weak_func_check finished
[*] Sun Mar  3 03:04:01 UTC 2024 - S20_shell_check finished
[*] Sun Mar  3 04:34:43 UTC 2024 - S115_usermode_emulator finished
[*] Sun Mar  3 04:46:14 UTC 2024 - S116_qemu_version_detection finished
[*] Sun Mar  3 05:37:10 UTC 2024 - S14_weak_func_radare_check finished
[*] Sun Mar  3 07:38:06 UTC 2024 - S09_firmware_base_version_check finished
[*] Sun Mar  3 08:59:31 UTC 2024 - S35_http_file_check finished
[*] Sun Mar  3 09:22:55 UTC 2024 - S19_apk_check finished
[*] Sun Mar  3 09:48:45 UTC 2024 - S24_kernel_bin_identifier finished
[*] Sun Mar  3 09:55:11 UTC 2024 - S26_kernel_vuln_verifier finished
[*] Sun Mar  3 09:58:43 UTC 2024 - S25_kernel_check finished
[!] Testing phase ended on Sun Mar  3 09:58:43 UTC 2024 and took about 2 days and 02:15:29

[!] Reporting phase started on Sun Mar  3 09:58:43 UTC 2024

[*] Sun Mar  3 09:58:43 UTC 2024 - F05_qs_resolver starting
[*] Sun Mar  3 09:58:44 UTC 2024 - F05_qs_resolver finished
[*] Sun Mar  3 09:58:44 UTC 2024 - F10_license_summary starting
[*] Sun Mar  3 09:58:54 UTC 2024 - F10_license_summary finished
[*] Sun Mar  3 09:58:54 UTC 2024 - F20_vul_aggregator starting
[*] Sun Mar  3 10:10:56 UTC 2024 - F20_vul_aggregator finished
[*] Sun Mar  3 10:10:56 UTC 2024 - F21_cyclonedx_sbom starting
[*] Sun Mar  3 10:10:59 UTC 2024 - F21_cyclonedx_sbom finished
[*] Sun Mar  3 10:10:59 UTC 2024 - F50_base_aggregator starting
[*] Sun Mar  3 10:11:18 UTC 2024 - F50_base_aggregator finished
[!] Test ended on Sun Mar  3 10:11:18 UTC 2024 and took about 2 days and 02:28:04

[*] Open the web-report with firefox /var/www/emba_logs/56137802-4901-4312-9362-4d00bd375624/emba_logs/html-report/index.html
  • emba_run.log is complete
ubuntu@csh-embark2:/var/www/emba_logs/56137802-4901-4312-9362-4d00bd375624$ tail -n 25 emba_run.log

[+] Identified 1028 CVE entries.
    Identified 396 High rated CVE entries / Exploits: 41
    Identified 584 Medium rated CVE entries / Exploits: 25
    Identified 48 Low rated CVE entries /Exploits: 0
    66 possible exploits available (5 Metasploit modules).
    Remote exploits: 2 / Local exploits: 7 / DoS exploits: 2 / Github PoCs: 0 / Known exploited vulnerabilities: 0 / Verified Exploits: 0

-----------------------------------------------------------------

....................[*] Sun Mar  3 10:11:18 UTC 2024 - F50_base_aggregator finished


[!] Test ended on Sun Mar  3 10:11:18 UTC 2024 and took about 2 days and 02:28:04

[*] Restoring directory permissions for user: www-embark
[*] Final cleanup started.
Error response from daemon: No such container: d6498f5507c77a8e13a81d402dafedc78feca6eeec26389ea5970d23294e110e
[*] EMBA finished analysis in docker container.

[*] Firmware tested: /var/www/active/56137802-4901-4312-9362-4d00bd375624/android-x86_64-9.0-r2.iso
[*] Log directory: /var/www/emba_logs/56137802-4901-4312-9362-4d00bd375624/emba_logs
[*] Open the web-report with firefox /var/www/emba_logs/56137802-4901-4312-9362-4d00bd375624/emba_logs/html-report/index.html

[*] Final cleanup started.
  • embark.log (I add some logging at logreader.py). It's strange that inotify suddenly stopped outputting logs. I suspect that the entire logreader.py may have exited. And then embark.log logging WARNING Run time of job "resource_tracker (trigger: cron[minute='0'], next run at: 2024-03-01 10:00:00 UTC)" was missed by 0:00:01.924320

scanning was finished at 2024-03-03 10:11:18 UTC, and maybe stuck at 2024-03-01 09:59:31 UTC

2024-03-01 09:59:31,322 586585 139879090480704 /var/www/embark/embark/logreader.py INFO got events flags.OPEN in /var/www/emba_logs/56137802-4901-4312-9362-4d00bd375624/emba_logs/emba.log
2024-03-01 09:59:31,322 586585 139879090480704 /var/www/embark/embark/logreader.py INFO got events flags.OPEN in /var/www/emba_logs/56137802-4901-4312-9362-4d00bd375624/emba_logs/emba.log
2024-03-01 09:59:31,323 586585 139879090480704 /var/www/embark/embark/logreader.py INFO got events flags.ACCESS in /var/www/emba_logs/56137802-4901-4312-9362-4d00bd375624/emba_logs/emba.log
2024-03-01 09:59:31,323 586585 139879090480704 /var/www/embark/embark/logreader.py INFO got events flags.ACCESS in /var/www/emba_logs/56137802-4901-4312-9362-4d00bd375624/emba_logs/emba.log
2024-03-01 09:59:31,334 586585 139879090480704 /var/www/embark/embark/logreader.py INFO got events flags.CLOSE_NOWRITE in /var/www/emba_logs/56137802-4901-4312-9362-4d00bd375624/emba_logs/emba.log
2024-03-01 09:59:31,334 586585 139879090480704 /var/www/embark/embark/logreader.py INFO got events flags.CLOSE_NOWRITE in /var/www/emba_logs/56137802-4901-4312-9362-4d00bd375624/emba_logs/emba.log
2024-03-01 09:59:31,466 586585 139879090480704 /var/www/embark/embark/logreader.py INFO got events flags.OPEN in /var/www/emba_logs/56137802-4901-4312-9362-4d00bd375624/emba_logs/emba.log
2024-03-01 09:59:31,466 586585 139879090480704 /var/www/embark/embark/logreader.py INFO got events flags.OPEN in /var/www/emba_logs/56137802-4901-4312-9362-4d00bd375624/emba_logs/emba.log
2024-03-01 09:59:31,467 586585 139879090480704 /var/www/embark/embark/logreader.py INFO got events flags.ACCESS in /var/www/emba_logs/56137802-4901-4312-9362-4d00bd375624/emba_logs/emba.log
2024-03-01 09:59:31,467 586585 139879090480704 /var/www/embark/embark/logreader.py INFO got events flags.ACCESS in /var/www/emba_logs/56137802-4901-4312-9362-4d00bd375624/emba_logs/emba.log
2024-03-01 09:59:31,467 586585 139879090480704 /var/www/embark/embark/logreader.py INFO got events flags.CLOSE_NOWRITE in /var/www/emba_logs/56137802-4901-4312-9362-4d00bd375624/emba_logs/emba.log
2024-03-01 09:59:31,467 586585 139879090480704 /var/www/embark/embark/logreader.py INFO got events flags.CLOSE_NOWRITE in /var/www/emba_logs/56137802-4901-4312-9362-4d00bd375624/emba_logs/emba.log
2024-03-01 10:00:01,925 586569 140437327173184 /var/www/.venv/lib/python3.10/site-packages/apscheduler/executors/base.py WARNING Run time of job "resource_tracker (trigger: cron[minute='0'], next run at: 2024-03-01 10:00:00 UTC)" was missed by 0:00:01.924320
2024-03-01 11:04:23,385 586569 140437327173184 /var/www/.venv/lib/python3.10/site-packages/apscheduler/executors/base.py WARNING Run time of job "resource_tracker (trigger: cron[minute='0'], next run at: 2024-03-01 12:00:00 UTC)" was missed by 0:04:23.365591
2024-03-01 12:01:59,808 586569 140437327173184 /var/www/.venv/lib/python3.10/site-packages/apscheduler/executors/base.py WARNING Run time of job "resource_tracker (trigger: cron[minute='0'], next run at: 2024-03-01 13:00:00 UTC)" was missed by 0:01:59.807778
  • And 2024-03-01 09:56:16 is the latest time Checking status success
2024-03-01 09:55:21,537 586585 139879090480704 /var/www/embark/embark/logreader.py INFO wrote file-diff
2024-03-01 09:55:21,537 586585 139879090480704 /var/www/embark/embark/logreader.py INFO wrote file-diff
2024-03-01 09:56:15,992 586585 139879090480704 /var/www/embark/embark/logreader.py INFO getting diff from /var/www/emba_logs/56137802-4901-4312-9362-4d00bd375624/emba_logs/emba.log
2024-03-01 09:56:15,992 586585 139879090480704 /var/www/embark/embark/logreader.py INFO getting diff from /var/www/emba_logs/56137802-4901-4312-9362-4d00bd375624/emba_logs/emba.log
2024-03-01 09:56:15,993 586585 139879090480704 /var/www/embark/embark/logreader.py INFO Got diff-output: [*] Fri Mar  1 09:56:15 UTC 2024 - S22_php_check finished
2024-03-01 09:56:15,993 586585 139879090480704 /var/www/embark/embark/logreader.py INFO Got diff-output: [*] Fri Mar  1 09:56:15 UTC 2024 - S22_php_check finished
2024-03-01 09:56:15,993 586585 139879090480704 /var/www/embark/embark/logreader.py INFO starting observers for log file /var/www/emba_logs/56137802-4901-4312-9362-4d00bd375624/emba_logs
2024-03-01 09:56:15,993 586585 139879090480704 /var/www/embark/embark/logreader.py INFO starting observers for log file /var/www/emba_logs/56137802-4901-4312-9362-4d00bd375624/emba_logs
2024-03-01 09:56:15,995 586585 139879090480704 /var/www/embark/embark/logreader.py INFO Status is 36, in phase 1, with modules 44
2024-03-01 09:56:15,995 586585 139879090480704 /var/www/embark/embark/logreader.py INFO Status is 36, in phase 1, with modules 44
2024-03-01 09:56:15,995 586585 139879090480704 /var/www/embark/embark/logreader.py INFO Appending status with message: {'percentage': 36.36363636363637, 'module': 'S22_php_check', 'phase': 'Testing phase started on Fri Mar  1 09:53:51 UTC 2024'}
2024-03-01 09:56:15,995 586585 139879090480704 /var/www/embark/embark/logreader.py INFO Appending status with message: {'percentage': 36.36363636363637, 'module': 'S22_php_check', 'phase': 'Testing phase started on Fri Mar  1 09:53:51 UTC 2024'}
2024-03-01 09:56:16,014 586585 139879090480704 /var/www/embark/embark/logreader.py INFO Checking status: {'work': False, 'analysis': '56137802-4901-4312-9362-4d00bd375624', 'finished': False, 'last_phase': 'Testing phase started on Fri Mar  1 09:53:51 UTC 2024', 'percentage': 36.36363636363637, 'phase_list': ['Pre-checking phase started on Fri Mar  1 07:43:20 UTC 2024', 'Pre-checking phase ended on Fri Mar  1 09:53:51 UTC 2024 and took about 0 days and 02:10:37 ', 'Testing phase started on Fri Mar  1 09:53:51 UTC 2024'], 'last_module': 'S22_php_check', 'last_update': '2024-03-01 09:56:15.995647+00:00', 'module_list': ['P02_firmware_bin_file_check', 'P05_patools_init', 'P35_UEFI_extractor', 'P55_unblob_extractor', 'P60_deep_extractor', 'P61_binwalk_extractor', 'P65_package_extractor', 'P99_prepare_analyzer', 'S02_UEFI_FwHunt', 'S21_python_check', 'S08_package_mgmt_extractor', 'S36_lighttpd', 'S90_mail_check', 'S80_cronjob_check', 'S40_weak_perm_check', 'S100_command_inj_check', 'S75_network_check', 'S55_history_file_check', 'S85_ssh_check', 'S07_bootloader_check', 'S06_distribution_identification', 'S95_interesting_files_check', 'S60_cert_file_check', 'S50_authentication_check', 'S65_config_file_check', 'S106_deep_key_search', 'S05_firmware_details', 'S22_php_check'], 'firmware_name': 'android-x86_64-9.0-r2.iso'}
2024-03-01 09:56:16,014 586585 139879090480704 /var/www/embark/embark/logreader.py INFO Checking status: {'work': False, 'analysis': '56137802-4901-4312-9362-4d00bd375624', 'finished': False, 'last_phase': 'Testing phase started on Fri Mar  1 09:53:51 UTC 2024', 'percentage': 36.36363636363637, 'phase_list': ['Pre-checking phase started on Fri Mar  1 07:43:20 UTC 2024', 'Pre-checking phase ended on Fri Mar  1 09:53:51 UTC 2024 and took about 0 days and 02:10:37 ', 'Testing phase started on Fri Mar  1 09:53:51 UTC 2024'], 'last_module': 'S22_php_check', 'last_update': '2024-03-01 09:56:15.995647+00:00', 'module_list': ['P02_firmware_bin_file_check', 'P05_patools_init', 'P35_UEFI_extractor', 'P55_unblob_extractor', 'P60_deep_extractor', 'P61_binwalk_extractor', 'P65_package_extractor', 'P99_prepare_analyzer', 'S02_UEFI_FwHunt', 'S21_python_check', 'S08_package_mgmt_extractor', 'S36_lighttpd', 'S90_mail_check', 'S80_cronjob_check', 'S40_weak_perm_check', 'S100_command_inj_check', 'S75_network_check', 'S55_history_file_check', 'S85_ssh_check', 'S07_bootloader_check', 'S06_distribution_identification', 'S95_interesting_files_check', 'S60_cert_file_check', 'S50_authentication_check', 'S65_config_file_check', 'S106_deep_key_search', 'S05_firmware_details', 'S22_php_check'], 'firmware_name': 'android-x86_64-9.0-r2.iso'}
2024-03-01 09:56:16,023 586585 139879090480704 /var/www/embark/embark/logreader.py INFO wrote file-diff
2024-03-01 09:56:16,023 586585 139879090480704 /var/www/embark/embark/logreader.py INFO wrote file-diff
  • I added the end log in boundedexecutor.py, but it seems that it was not outputted (I am not familiar with Python and I don't know if there is a problem with my writing).

image

@BenediktMKuehne
Copy link
Member

Thank you, will do some tests

@torabi12
Copy link

torabi12 commented Mar 4, 2024

My scan also hangs at 46% with rootfs.ext4, I started it 3 days before. :(

@BenediktMKuehne
Copy link
Member

looks like an issue with the f50 read_in
image

working on a fix now

@mobilemutex
Copy link

mobilemutex commented Mar 13, 2024

I was able to manually finish the report generation when this happened to me. This may depend on where it times out and where the actual failure happens, but I had the same log output as BenediktMKuehne in the above screenshot.

From the /var/www directory, I ran the django admin shell:
sudo PYTHONPATH=$PYTHONPATH:/var/www/embark DJANGO_SETTINGS_MODULE=embark.settings.deploy .venv/bin/python3 embark/manage.py shell

Then, I ran the following in the django admin python shell:

>>> from porter import importer
>>> from uploader.models import FirmwareAnalysis
>>> from django.utils import timezone
>>> importer.result_read_in(<analysis id here>)
>>> analysis = FirmwareAnalysis.objects.get(<analysis id>)
>>> analysis.end_date = timezone.now()
>>> analysis.scan_time = timezone.now() - analysis.start_date
>>> analysis.duration = str(analysis.scan_time)
>>> analysis.finished = True
>>> analysis.failed = exit_fail
>>> analysis.save(update_fields=["end_date", "scan_time", "duration", "finished", "failed"])

Which essentially just re-ran the call to importer.result_read_in() and then finalized the db entry the same way the boundedexecutor.py file does:

cls.csv_read(analysis_id=analysis_id, _path=csv_log_location, _cmd=cmd)

def csv_read(cls, analysis_id, _path, _cmd):
"""
This job reads the F50_aggregator file and stores its content into the Result model
"""
return result_read_in(analysis_id=analysis_id)

analysis.end_date = timezone.now()
analysis.scan_time = timezone.now() - analysis.start_date
analysis.duration = str(analysis.scan_time)
analysis.finished = True
analysis.failed = exit_fail
analysis.save(update_fields=["end_date", "scan_time", "duration", "finished", "failed"])

I think (not 100% sure) the actual issue is that the connection to MySQL times out somehow. Hence the error message specifying the wait_timeout and interactive_timeout variables, which are usually specified in the mysql.cnf file. I'm not familiar with Django, so I don't know if that's where the settings should go or not in this case. This is just a guess but looking at the order of the error messages printed before the boundedexecutor.py exception, I think that it happens somewhere around the below line in importer.py, where it tries to get the FirmwareAnalysis object for the current analysis id.

firmware_analysis=FirmwareAnalysis.objects.get(id=analysis_id)

I'm not 100% sure of this but something is triggering the exception in boundedexecutor.py and it's after the call to importer.read_csv() (since the result dict prints in the log), and, presumably, before the importer.result_read_in() function returns.

@mobilemutex
Copy link

I was able to fix the issue with boundedexecutor.py not completing properly. It does seem like the connection to the mysql server gets closed by mysql due to inactivity. The default wait_timeout for mysql is 8 hours, so it seems like any analysis that has a module that takes longer than 8 hours can cause this.

This can be tested on a shorter cycle by setting the wait_timeout parameter in mysql.cnf to a smaller value (It needs to be more than 1 hour, though, otherwise there is an error in the apscheduler that causes a python exception in the resource_tracker job due to the mysql timeout. But, I'm not sure if that actually should be another issue or not. That same issue causes a warning in the logs every hour after the initial 8 hours when the wait_timeout is set to the default, but only seems to cause an exception when it's under 1 hour. Maybe the resource_tracker job needs the @util.close_old_connections decorator since it should be present for any function that accesses the database? wait_timeout shouldn't be less than an hour though, so maybe it doesn't matter. This also seems like it could be the cause of the "next run ... was missed by" logs in the previous comments.)

A quick hack is to set the wait_timeout value in mysql.cnf to a value larger than the possible duration of the analysis, but that's not a proper fix.

To fix:

I added a call to django.db.close_old_connections to the boundedexecutor.py file. It needs to be imported, and then I inserted the call at line 98, after the emba execution returns and before the f50_aggregator is processed.

from djang.db import close_old_connections
...
close_old_connections()

return_code = proc.wait()
# success
logger.info("Success: %s", cmd)
logger.info("EMBA returned: %d", return_code)
if return_code != 0:
raise BoundedException("EMBA has non zero exit-code")
# get csv log location
csv_log_location = f"{settings.EMBA_LOG_ROOT}/{analysis_id}/emba_logs/csv_logs/f50_base_aggregator.csv"

After adding that call and re-running analysis on the same firmware that caused the issue, it completed correctly. I am not sure if this is the only place this fix needs to be inserted. It seems like there could be a similar gap in database accesses in the logreader, which could possibly cause the same problem if it tries to access the database after an 8 hour gap before close_old_connections gets called by boundedexecutor.py. I have not tested this extensively enough to confirm that.

@torabi12
Copy link

It would be great to test this with other FWs also....

@torabi12
Copy link

torabi12 commented Mar 27, 2024

All my more days long tests are not available in EMBArk. Maybe this fix solve the issue I hope.
image

@torabi12
Copy link

This would be a very useful improvement, because many tests run fine, but the report is inaccessible on EMBArk and you can only copy the results from the file system.

@BenediktMKuehne
Copy link
Member

Sorry for the delay, will try to fix within the next week

@BenediktMKuehne BenediktMKuehne self-assigned this Apr 12, 2024
@BenediktMKuehne
Copy link
Member

Can anyone confirm that the issue is fixed?

@gitsang
Copy link
Author

gitsang commented Apr 26, 2024

Can anyone confirm that the issue is fixed?

Was this fix by https://github.com/BenediktMKuehne/embark/tree/196-scanning-cannot-be-completed-correctly?

I will start verification in the next few days.

@BenediktMKuehne
Copy link
Member

It's more of a workaround since the underlying issue is somewhere in mysql(/its config)
But yes the fix suggested was merged in that PR

@spon94
Copy link

spon94 commented Apr 28, 2024

I tested it,it took about 13h30mins to finish and report is accessible on EMBArk.

@gitsang
Copy link
Author

gitsang commented May 22, 2024

Sorry for delay. I have tested https://sourceforge.net/projects/android-x86/files/Release%209.0/android-x86_64-9.0-r2.iso/download (sha256: F7EB8FC56F29AD5432335DC054183ACF086C539F3990F0B6E9FF58BD6DF4604E), it took about 4 day and appears to be working well and has successfully completed the task.

image

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
can't reproduce We were not able to reproduce the issue with the provided information EMBArk
Projects
None yet
Development

When branches are created from issues, their pull requests are automatically linked.

6 participants