Почему не запускается скрипт через systemd?

Question

[Ivan Yakushenko]

Ubuntu 18.04.
/etc/systemd/system/start_bot.service:

[Unit]
Description=VkImageBot
After=multi-user.target

[Service]
Type=idle
ExecStart=/usr/bin/python3 /home/ftproot/vk_image_bot.py
Restart=always

[Install]
WantedBy=multi-user.target

После выполнения sudo systemctl start sitbot.service ничего, sudo systemctl status sitbot.service:

● start_bot.service - VkImageBot
   Loaded: loaded (/etc/systemd/system/start_bot.service; enabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Fri 2019-05-03 12:44:51 CEST; 1s ago
  Process: 28107 ExecStart=/usr/bin/python3 /home/ftproot/vk_image_bot/start_bot.py (code=exited, status=1/FAILUR
 Main PID: 28107 (code=exited, status=1/FAILURE)

May 03 12:44:51 shostvo100vkbot.tk systemd[1]: start_bot.service: Main process exited, code=exited, status=1/FAIL
May 03 12:44:51 shostvo100vkbot.tk systemd[1]: start_bot.service: Failed with result 'exit-code'.
May 03 12:44:51 shostvo100vkbot.tk systemd[1]: start_bot.service: Service hold-off time over, scheduling restart.
May 03 12:44:51 shostvo100vkbot.tk systemd[1]: start_bot.service: Scheduled restart job, restart counter is at 5.
May 03 12:44:51 shostvo100vkbot.tk systemd[1]: Stopped VkImageBot.
May 03 12:44:51 shostvo100vkbot.tk systemd[1]: start_bot.service: Start request repeated too quickly.
May 03 12:44:51 shostvo100vkbot.tk systemd[1]: start_bot.service: Failed with result 'exit-code'.
May 03 12:44:51 shostvo100vkbot.tk systemd[1]: Failed to start VkImageBot.
lines 1-14/14 (END)

Answer 1

[pcdesign]

Чтобы победить вот эту строку

start_bot.service: Start request repeated too quickly.

Можно добавить:

Restart=always
RestartSec=15

А на счет того почему падает сам питоновский скрипт - стоит логировать ошибку куда-нибудь в файл.

Comments

[Ivan Yakushenko]

● start_bot.service - VkImageBot
Loaded: loaded (/etc/systemd/system/start_bot.service; enabled; vendor preset: enabled)
Active: activating (auto-restart) (Result: exit-code) since Fri 2019-05-03 12:55:36 CEST; 1s ago
Process: 28190 ExecStart=/usr/bin/python3 /home/ftproot/vk_image_bot/start_bot.py (code=exited, status=1/FAILUR
Main PID: 28190 (code=exited, status=1/FAILURE)

May 03 12:55:36 shostvo100vkbot.tk systemd[1]: start_bot.service: Main process exited, code=exited, status=1/FAIL
May 03 12:55:36 shostvo100vkbot.tk systemd[1]: start_bot.service: Failed with result 'exit-code'.

[pcdesign]

Ivan Yakushenko, а этот скрипт работает в виртуальном окружении?

[Ivan Yakushenko]

Если просто написать python3 /home/ftproot/vk_image_bot/start_bot.py то запускается и работает вообще без проблем, иногда только крашится + иногда сам сервер перезагружается, по-этому нужно что-то, что автоматически будет стартовать бота при запуске системы и в случае ошибки бота.

[Ivan Yakushenko]

pcdesign, он не в виртуальном окружении работает. Просто в систему установлен питон + нужные библиотеки.

[pcdesign]

ExecStart=/usr/bin/python3 /home/ftproot/vk_image_bot/start_bot.py > /home/ftproot/vk_image_bot/log.log

А есть вывод в файл направить? Вот типа того.

[pcdesign]

И потом посмотрим во внутренности этого файла

[Ivan Yakushenko]

pcdesign, так, во-первых я ничего не делал, но бот запустился. добил параметр лога, сам файл создался но он пустой. В самом боте есть вывод выполненных команд в консоль через print(), я могу как-то отслеживать эти действия, потому что туда-же у меня выводится несколько исключений, за которыми мне хотелось-бы следить.

[pfg21]

вывод скрипта отображается в логе системд.
он пустой - предположу, питонов бот написан без дебаг-сообщений.

[Ivan Yakushenko]

pfg21, все, что мне нужно было я выводил командой print() - список успешных команд и все исключения, неужели я никак не могу отслеживать это?

[pcdesign]

Ivan Yakushenko, вам нужно освоить логирование
https://python-scripts.com/logging-python
И там где вы писали print(), вместо этого писать logging.debug()
И направлять этот лог в файл.

[Ivan Yakushenko]

pcdesign, а конфликта не будет? Я в ExecStart добавил > /home/ftproot/vk_image_bot/log.log, если теперь тоже самое сделаю в скрипте Logging.basicConfig(filename="log.log", level=(logging.INFO, logging.DEBUG, logging.ERROR)), они не будут мешать друг другу/дублировать логи?

[pcdesign]

Ivan Yakushenko,

1) перенаправление > уберите из ExecStart

2) level=logging.DEBUG -этого достаточно

3) И путь стоит полный указывать filename="/home/ftproot/vk_image_bot/log.log"

[Ivan Yakushenko]

pcdesign, спасибо, буду пробовать и смотреть!

[Ivan Yakushenko]

pcdesign, если скрипт завершается с Exception in thread Thread-2: то systemd его не перезапускает - это можно как-то вылечить?

[pcdesign]

Ivan Yakushenko, надо оборачивать такого плана вещи в try.
Отлавливать ошибку и выводить ее в файл.

try:
    # Код
except Exception as e:
    logging.debug(e)

[pcdesign]

И вообще любые внешние соединения надо оборачивать в try, это хорошая практика.
Мы не знаем что там придет и придет ли вообще.

[Ivan Yakushenko]

pcdesign, а если я изначально не знаю что именно вызывает эту ошибку, а в коде несколько сотен строк плюс я не знаю какие именно действие пользователя вызывает ошибку? как с такими вещами поступать?

[pcdesign]

Ivan Yakushenko, целиком весь код засовывать в try не есть гуд. Но на этапе отладки можно. Надо же выяснить из-за чего он валится.

Просто по опыту могу сказать, что в большинстве случаев при работе с API, не важно будь то телеграмм или вк или еще что-нибудь падает при очень частых запросах. Так что где-нибудь стоит воткнуть sleep(2) в while, чтобы скрипт не насиловал слишком часто сторонние API.

[Ivan Yakushenko]

pcdesign, из-за незнания асинхронного программирования у меня просто зверски-костыльный код, в итоге на выходе при вызова функции, к примеру, наложении фильтра, где пользователь присылает фото а в ответ ему отдается обработанное изображение у меня такая инфа:

spoiler

2019-05-03 14:16:20,945:DEBUG:https://lp.vk.com:443 "GET /wh181557869?act=a_check&key=a1e4be078f2eb43ae46fd911b088b7b57225b795&ts=2691&wait=15 HTTP/1.1" 200 28
2019-05-03 14:16:35,966:DEBUG:https://lp.vk.com:443 "GET /wh181557869?act=a_check&key=a1e4be078f2eb43ae46fd911b088b7b57225b795&ts=2691&wait=15 HTTP/1.1" 200 28
2019-05-03 14:16:50,982:DEBUG:https://lp.vk.com:443 "GET /wh181557869?act=a_check&key=a1e4be078f2eb43ae46fd911b088b7b57225b795&ts=2691&wait=15 HTTP/1.1" 200 28
2019-05-03 14:17:05,998:DEBUG:https://lp.vk.com:443 "GET /wh181557869?act=a_check&key=a1e4be078f2eb43ae46fd911b088b7b57225b795&ts=2691&wait=15 HTTP/1.1" 200 28
2019-05-03 14:17:21,014:DEBUG:https://lp.vk.com:443 "GET /wh181557869?act=a_check&key=a1e4be078f2eb43ae46fd911b088b7b57225b795&ts=2691&wait=15 HTTP/1.1" 200 28
2019-05-03 14:17:36,031:DEBUG:https://lp.vk.com:443 "GET /wh181557869?act=a_check&key=a1e4be078f2eb43ae46fd911b088b7b57225b795&ts=2691&wait=15 HTTP/1.1" 200 28
2019-05-03 14:17:51,048:DEBUG:https://lp.vk.com:443 "GET /wh181557869?act=a_check&key=a1e4be078f2eb43ae46fd911b088b7b57225b795&ts=2691&wait=15 HTTP/1.1" 200 28
2019-05-03 14:18:06,065:DEBUG:https://lp.vk.com:443 "GET /wh181557869?act=a_check&key=a1e4be078f2eb43ae46fd911b088b7b57225b795&ts=2691&wait=15 HTTP/1.1" 200 28
2019-05-03 14:18:21,085:DEBUG:https://lp.vk.com:443 "GET /wh181557869?act=a_check&key=a1e4be078f2eb43ae46fd911b088b7b57225b795&ts=2691&wait=15 HTTP/1.1" 200 28
2019-05-03 14:18:36,104:DEBUG:https://lp.vk.com:443 "GET /wh181557869?act=a_check&key=a1e4be078f2eb43ae46fd911b088b7b57225b795&ts=2691&wait=15 HTTP/1.1" 200 28
2019-05-03 14:18:51,123:DEBUG:https://lp.vk.com:443 "GET /wh181557869?act=a_check&key=a1e4be078f2eb43ae46fd911b088b7b57225b795&ts=2691&wait=15 HTTP/1.1" 200 28
2019-05-03 14:19:02,710:DEBUG:https://lp.vk.com:443 "GET /wh181557869?act=a_check&key=a1e4be078f2eb43ae46fd911b088b7b57225b795&ts=2691&wait=15 HTTP/1.1" 200 1248
2019-05-03 14:19:02,741:DEBUG:https://api.vk.com:443 "POST /method/users.get HTTP/1.1" 200 114
2019-05-03 14:19:06,344:DEBUG:https://lp.vk.com:443 "GET /wh181557869?act=a_check&key=a1e4be078f2eb43ae46fd911b088b7b57225b795&ts=2692&wait=15 HTTP/1.1" 200 317
2019-05-03 14:19:06,372:DEBUG:https://api.vk.com:443 "POST /method/users.get HTTP/1.1" 200 114
2019-05-03 14:19:06,811:DEBUG:https://api.vk.com:443 "POST /method/messages.send HTTP/1.1" 200 37
2019-05-03 14:19:06,812:DEBUG:Command: COMMAND FILTERS successful for 463080516

А таких функций уйма и будет больше.
time.sleep() и так стоит в каждом цикле.
Бот крутится в группе с 500к человек и с вполне большим активом и все это без асинхронки - чисто на потоках и циклах. Работает, иногда неизвестно почему и неизвестно из-за чего происходят исключения.
Заменил все принты на дебаг, сейчас очень много функций обернул в блоки try-except, буду смотреть где и что, а то бот еще будет обрастать функционалом.

Answer 2

[pfg21]

данных не хвататет.
посмотреть что не нравится vk_image_bot.py что он завершается и выкидывает статус 1.
мож пользователь не подходит, мож еще чаго...

напихать в vk_image_bot.py побольше информационных сообщений. а то отладка немой проги хуже секса с холодной женщиной...

Comments

[Ivan Yakushenko]

Сам по себе бот стартует и работает без проблем, никаких ошибок нет, но при попытке запустить его через systemd не получается.

[pfg21]

Ivan Yakushenko, пропиши в скрипт запуска пользователя, из-под которого запускаешь вручную.
мож прокатит.
а так дебажъ внутренности питоновского крипта - ищи место где не запускается.

Answer 3

[zoldaten]

journalctl -u charge_check.service -b
посмотри, что не нравится.
еще помогает дописывание usera и directory:
[Service]
User=pi
Type=simple
Restart=always
RestartSec=5
WorkingDirectory=/home/pi/Desktop
ExecStart=/usr/bin/python3 charge_check.py