Arch Linux

pepper

Member

Registered: 2017-12-09

Posts: 116

nzbhydra2 service can't start

Hello, I installed nzbhydra2-bin (5.3.10) from AUR, it worked for months, after latest update (yesterday) it can't run anymore. I tried to downgrade the aur package to 5.3.8 version (that is the version that was working 1-2 days ago).
If I install nzbhydra in a new fresh archlinux machine, it works.

Can you help me to find the error output?

sudo systemctl status nzbhydra2

× nzbhydra2.service - NZBHydra2 Daemon
     Loaded: loaded (/usr/lib/systemd/system/nzbhydra2.service; enabled; preset: disabled)
     Active: failed (Result: start-limit-hit) since Wed 2024-03-20 10:45:48 CET; 2s ago
   Duration: 139ms
       Docs: https://github.com/theotherp/nzbhydra2
    Process: 17961 ExecStart=/usr/bin/nzbhydra2 --nobrowser --datafolder /var/lib/nzbhydra2 (code=exited, status=0/SUCCESS)
   Main PID: 17961 (code=exited, status=0/SUCCESS)
        CPU: 64ms

mar 20 10:45:48 dpc systemd[1]: nzbhydra2.service: Scheduled restart job, restart counter is at 5.
mar 20 10:45:48 dpc systemd[1]: nzbhydra2.service: Start request repeated too quickly.
mar 20 10:45:48 dpc systemd[1]: nzbhydra2.service: Failed with result 'start-limit-hit'.
mar 20 10:45:48 dpc systemd[1]: Failed to start NZBHydra2 Daemon.

journalctl -eu nzbhydra2

mar 20 10:45:47 dpc systemd[1]: nzbhydra2.service: Scheduled restart job, restart counter is at 3.
mar 20 10:45:47 dpc systemd[1]: Started NZBHydra2 Daemon.
mar 20 10:45:47 dpc nzbhydra2[17950]: Logging wrapper output to /var/lib/nzbhydra2/logs/wrapper.log
mar 20 10:45:47 dpc nzbhydra2[17950]: 2024-03-20 10:45:47,358  INFO - Release type native forced by environment variable
mar 20 10:45:47 dpc nzbhydra2[17950]: 2024-03-20 10:45:47,359  INFO - Starting NZBHydra main process with command line: ./core -Xmx256M -DfromWrapper=true -DinternalApiKey=XXXXXXXXXXXXXXXXXXX -Dsun.security.pkcs11.enable-solaris=false -Dfile.encoding=UTF8 -Dspring.output.ansi.ena>
mar 20 10:45:47 dpc nzbhydra2[17950]: 2024-03-20 10:45:47,429  WARNING - Unable to read control ID from /var/lib/nzbhydra2/control.id: [Errno 2] No such file or directory: '/var/lib/nzbhydra2/control.id'. Falling back to process return code -7
mar 20 10:45:47 dpc nzbhydra2[17950]: 2024-03-20 10:45:47,429  INFO - NZBHydra main process has terminated for shutdown
mar 20 10:45:47 dpc systemd[1]: nzbhydra2.service: Deactivated successfully.
mar 20 10:45:47 dpc systemd[1]: nzbhydra2.service: Scheduled restart job, restart counter is at 4.
mar 20 10:45:47 dpc systemd[1]: Started NZBHydra2 Daemon.
mar 20 10:45:47 dpc nzbhydra2[17961]: Logging wrapper output to /var/lib/nzbhydra2/logs/wrapper.log
mar 20 10:45:47 dpc nzbhydra2[17961]: 2024-03-20 10:45:47,617  INFO - Release type native forced by environment variable
mar 20 10:45:47 dpc nzbhydra2[17961]: 2024-03-20 10:45:47,618  INFO - Starting NZBHydra main process with command line: ./core -Xmx256M -DfromWrapper=true -DinternalApiKey=XXXXXXXXXXXXXXXXXXX -Dsun.security.pkcs11.enable-solaris=false -Dfile.encoding=UTF8 -Dspring.output.ansi.ena>
mar 20 10:45:47 dpc nzbhydra2[17961]: 2024-03-20 10:45:47,686  WARNING - Unable to read control ID from /var/lib/nzbhydra2/control.id: [Errno 2] No such file or directory: '/var/lib/nzbhydra2/control.id'. Falling back to process return code -7
mar 20 10:45:47 dpc nzbhydra2[17961]: 2024-03-20 10:45:47,686  INFO - NZBHydra main process has terminated for shutdown
mar 20 10:45:47 dpc systemd[1]: nzbhydra2.service: Deactivated successfully.
mar 20 10:45:48 dpc systemd[1]: nzbhydra2.service: Scheduled restart job, restart counter is at 5.
mar 20 10:45:48 dpc systemd[1]: nzbhydra2.service: Start request repeated too quickly.
mar 20 10:45:48 dpc systemd[1]: nzbhydra2.service: Failed with result 'start-limit-hit'.
mar 20 10:45:48 dpc systemd[1]: Failed to start NZBHydra2 Daemon.
mar 20 11:25:25 dpc systemd[1]: Started NZBHydra2 Daemon.
mar 20 11:25:25 dpc nzbhydra2[27231]: Logging wrapper output to /var/lib/nzbhydra2/logs/wrapper.log
mar 20 11:25:25 dpc nzbhydra2[27231]: 2024-03-20 11:25:25,197  INFO - Release type native forced by environment variable
mar 20 11:25:25 dpc nzbhydra2[27231]: 2024-03-20 11:25:25,199  INFO - Starting NZBHydra main process with command line: ./core -Xmx256M -DfromWrapper=true -DinternalApiKey=XXXXXXXXXXXXXXXXXXX -Dsun.security.pkcs11.enable-solaris=false -Dfile.encoding=UTF8 -Dspring.output.ansi.ena>
mar 20 11:25:25 dpc nzbhydra2[27231]: 2024-03-20 11:25:25,269  WARNING - Unable to read control ID from /var/lib/nzbhydra2/control.id: [Errno 2] No such file or directory: '/var/lib/nzbhydra2/control.id'. Falling back to process return code -7
mar 20 11:25:25 dpc nzbhydra2[27231]: 2024-03-20 11:25:25,269  INFO - NZBHydra main process has terminated for shutdown
mar 20 11:25:25 dpc systemd[1]: nzbhydra2.service: Deactivated successfully.
mar 20 11:25:25 dpc systemd[1]: nzbhydra2.service: Scheduled restart job, restart counter is at 1.
mar 20 11:25:25 dpc systemd[1]: Started NZBHydra2 Daemon.
mar 20 11:25:25 dpc nzbhydra2[27255]: Logging wrapper output to /var/lib/nzbhydra2/logs/wrapper.log
mar 20 11:25:25 dpc nzbhydra2[27255]: 2024-03-20 11:25:25,667  INFO - Release type native forced by environment variable
mar 20 11:25:25 dpc nzbhydra2[27255]: 2024-03-20 11:25:25,669  INFO - Starting NZBHydra main process with command line: ./core -Xmx256M -DfromWrapper=true -DinternalApiKey=XXXXXXXXXXXXXXXXXXX -Dsun.security.pkcs11.enable-solaris=false -Dfile.encoding=UTF8 -Dspring.output.ansi.ena>
mar 20 11:25:25 dpc nzbhydra2[27255]: 2024-03-20 11:25:25,738  WARNING - Unable to read control ID from /var/lib/nzbhydra2/control.id: [Errno 2] No such file or directory: '/var/lib/nzbhydra2/control.id'. Falling back to process return code -7
mar 20 11:25:25 dpc nzbhydra2[27255]: 2024-03-20 11:25:25,739  INFO - NZBHydra main process has terminated for shutdown
mar 20 11:25:25 dpc systemd[1]: nzbhydra2.service: Deactivated successfully.
mar 20 11:25:26 dpc systemd[1]: nzbhydra2.service: Scheduled restart job, restart counter is at 2.
mar 20 11:25:26 dpc systemd[1]: Started NZBHydra2 Daemon.
mar 20 11:25:26 dpc nzbhydra2[27267]: Logging wrapper output to /var/lib/nzbhydra2/logs/wrapper.log
mar 20 11:25:26 dpc nzbhydra2[27267]: 2024-03-20 11:25:26,149  INFO - Release type native forced by environment variable
mar 20 11:25:26 dpc nzbhydra2[27267]: 2024-03-20 11:25:26,150  INFO - Starting NZBHydra main process with command line: ./core -Xmx256M -DfromWrapper=true -DinternalApiKey=XXXXXXXXXXXXXXXXXXX -Dsun.security.pkcs11.enable-solaris=false -Dfile.encoding=UTF8 -Dspring.output.ansi.ena>
mar 20 11:25:26 dpc nzbhydra2[27267]: 2024-03-20 11:25:26,223  WARNING - Unable to read control ID from /var/lib/nzbhydra2/control.id: [Errno 2] No such file or directory: '/var/lib/nzbhydra2/control.id'. Falling back to process return code -7
mar 20 11:25:26 dpc nzbhydra2[27267]: 2024-03-20 11:25:26,224  INFO - NZBHydra main process has terminated for shutdown
mar 20 11:25:26 dpc systemd[1]: nzbhydra2.service: Deactivated successfully.
mar 20 11:25:26 dpc systemd[1]: nzbhydra2.service: Scheduled restart job, restart counter is at 3.
mar 20 11:25:26 dpc systemd[1]: Started NZBHydra2 Daemon.
mar 20 11:25:26 dpc nzbhydra2[27279]: Logging wrapper output to /var/lib/nzbhydra2/logs/wrapper.log
mar 20 11:25:26 dpc nzbhydra2[27279]: 2024-03-20 11:25:26,666  INFO - Release type native forced by environment variable
mar 20 11:25:26 dpc nzbhydra2[27279]: 2024-03-20 11:25:26,667  INFO - Starting NZBHydra main process with command line: ./core -Xmx256M -DfromWrapper=true -DinternalApiKey=XXXXXXXXXXXXXXXXXXX -Dsun.security.pkcs11.enable-solaris=false -Dfile.encoding=UTF8 -Dspring.output.ansi.ena>
mar 20 11:25:26 dpc nzbhydra2[27279]: 2024-03-20 11:25:26,739  WARNING - Unable to read control ID from /var/lib/nzbhydra2/control.id: [Errno 2] No such file or directory: '/var/lib/nzbhydra2/control.id'. Falling back to process return code -7
mar 20 11:25:26 dpc nzbhydra2[27279]: 2024-03-20 11:25:26,740  INFO - NZBHydra main process has terminated for shutdown
mar 20 11:25:26 dpc systemd[1]: nzbhydra2.service: Deactivated successfully.
mar 20 11:25:27 dpc systemd[1]: nzbhydra2.service: Scheduled restart job, restart counter is at 4.
mar 20 11:25:27 dpc systemd[1]: Started NZBHydra2 Daemon.
mar 20 11:25:27 dpc nzbhydra2[27293]: Logging wrapper output to /var/lib/nzbhydra2/logs/wrapper.log
mar 20 11:25:27 dpc nzbhydra2[27293]: 2024-03-20 11:25:27,091  INFO - Release type native forced by environment variable
mar 20 11:25:27 dpc nzbhydra2[27293]: 2024-03-20 11:25:27,092  INFO - Starting NZBHydra main process with command line: ./core -Xmx256M -DfromWrapper=true -DinternalApiKey=XXXXXXXXXXXXXXXXXXX -Dsun.security.pkcs11.enable-solaris=false -Dfile.encoding=UTF8 -Dspring.output.ansi.ena>
mar 20 11:25:27 dpc nzbhydra2[27293]: 2024-03-20 11:25:27,149  WARNING - Unable to read control ID from /var/lib/nzbhydra2/control.id: [Errno 2] No such file or directory: '/var/lib/nzbhydra2/control.id'. Falling back to process return code -7
mar 20 11:25:27 dpc nzbhydra2[27293]: 2024-03-20 11:25:27,149  INFO - NZBHydra main process has terminated for shutdown
mar 20 11:25:27 dpc systemd[1]: nzbhydra2.service: Deactivated successfully.
mar 20 11:25:27 dpc systemd[1]: nzbhydra2.service: Scheduled restart job, restart counter is at 5.
mar 20 11:25:27 dpc systemd[1]: nzbhydra2.service: Start request repeated too quickly.
mar 20 11:25:27 dpc systemd[1]: nzbhydra2.service: Failed with result 'start-limit-hit'.
mar 20 11:25:27 dpc systemd[1]: Failed to start NZBHydra2 Daemon.

wrapper.log

2024-03-20 09:04:37,359  INFO - Starting NZBHydra main process with command line: ./core -Xmx256M -DfromWrapper=true -DinternalApiKey=CENSORED -Dsun.security.pkcs11.enable-solaris=false -Dfile.encoding=UTF8 -Dspring.output.ansi.enabled=ALWAYS --nobrowser --datafolder /var/lib/nzbhydra2 in folder /usr/lib/nzbhydra2
2024-03-20 09:04:37,414  WARNING - Unable to read control ID from /var/lib/nzbhydra2/control.id: [Errno 2] No such file or directory: '/var/lib/nzbhydra2/control.id'. Falling back to process return code -7
2024-03-20 09:04:37,414  INFO - NZBHydra main process has terminated for shutdown

I tried to run it manually but I'm not sure if it ran:
sudo -u nzbhydra2 /usr/lib/nzbhydra2/core -Xmx256M -DfromWrapper=true -DinternalApiKey=XXXXXXXX -Dsun.security.pkcs11.enable-solaris=false -Dfile.encoding=UTF8 -Dspring.output.ansi.enabled=ALWAYS --nobrowser --datafolder /var/lib/nzbhydra2 in folder /usr/lib/nzbhydra2

[1]    60426 bus error  sudo -u nzbhydra2 /usr/lib/nzbhydra2/core -Xmx256M -DfromWrapper=true

Last edited by pepper (2024-03-21 10:07:32)

jkhsjdhjs

Member

Registered: 2017-09-05

Posts: 39

Re: nzbhydra2 service can't start

The real error here is the bus error, that can be observed when starting `/usr/lib/nzbhydra2/core` manually, i.e.

$ sudo -u nzbhydra2 /usr/lib/nzbhydra2/core -Xmx256M -DfromWrapper=true -DinternalApiKey=XXXXXXXX -Dsun.security.pkcs11.enable-solaris=false -Dfile.encoding=UTF8 -Dspring.output.ansi.enabled=ALWAYS --nobrowser --datafolder /var/lib/nzbhydra2
[1]    60426 bus error  sudo -u nzbhydra2 /usr/lib/nzbhydra2/core -Xmx256M -DfromWrapper=true

As @pepper wrote, this started happening after the upgrade to nzbhydra2 5.3.10. However, now the same errors also occurs with 5.3.8, the version, that @pepper previously used without issues.
The question is: What can cause such bus errors? How can it be investigated?

See also: https://github.com/theotherp/nzbhydra2/issues/925

jkhsjdhjs

Member

Registered: 2017-09-05

Posts: 39

Re: nzbhydra2 service can't start

Fix is to disable the makepkg debug option, via !debug in makepkg.conf or in the PKGBUILD. I don't know why the debug option causes problems here. The nzbhydra AUR packages have been updated to disable the option.