Устранение неполадок при сбое службы mongodb - PullRequest
Новая
       7

Устранение неполадок при сбое службы mongodb

0 голосов
/ 16 января 2019

Я запускаю программу на python на raspberry pi (Linux), которая регистрирует данные в mongodb (используя модуль pymongo). У меня проблемы с пониманием, когда служба mongodb перестает работать или почему она остановится.

Прямо сейчас у меня настроены функции моей программы, так что если им не удается получить доступ к mongodb (получить исключения для соединения pymongo), они пытаются перезапустить службу, подождать десять секунд, а затем повторить попытку операции. Эти функции рекурсивны примерно так: 

def get_database_collection():
     try:
          # code to get document
          return document
     except Exception:
          # code to log exception in my log files
          start_mongo_service()
          get_database_collection()

А вот так выглядит функция start_mongo_service (): 

def start_mongo_service():
     try:
          subprocess.call(["sudo", "service", "mongodb", "start"])
          time.sleep(10)
          return True
     except Exception:
          # code to log exception in my log files (Could not start_mongo_service)
          database_logger = logging.getLogger('database_thread')
          database_logger.exception("Could not start_mongo_service")
          time.sleep(10)
          return False

Теперь я знаю, что перехватывать все исключения - это плохая практика, но я делаю это потому, что не хочу, чтобы мой код когда-либо падал, и регистрирую любое возникающее исключение, чтобы я мог проверить поведение кода.

Итак, вчера моя программа потерпела крах, и на консоли была выдана ошибка: MaximumRecursionDepth превышен, что, как я предполагаю, означает, что он зациклился 1000 раз и все еще не может избежать своего исключения. Вот как выглядит журнал программы: 

2019-01-15 18:12:50,000 - ERROR - database_thread - Could not start_mongo_service
Traceback (most recent call last):
  File "gateway-embedded-code/database.py", line 89, in update_status_collection
AttributeError: 'NoneType' object has no attribute 'update'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "pymongo/mongo_client.py", line 266, in __init__
  File "pymongo/mongo_client.py", line 641, in __find_node
pymongo.errors.AutoReconnect: could not connect to localhost:27017: [Errno 110] Connection timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "gateway-embedded-code/database.py", line 35, in get_database_collection
  File "pymongo/mongo_client.py", line 269, in __init__
pymongo.errors.ConnectionFailure: could not connect to localhost:27017: [Errno 110] Connection timed out

Вышеуказанные исключения пимонго возникали много раз, я сократил их для публикации здесь. Затем я попытался просмотреть собственные журналы mongodb в / var / log / mongodb, и последняя запись была в 15 января 17:51:54! После этого в журналах ничего не было на тот день ... Я думаю, служба остановилась, и моя программа не смогла перезапустить ее, поэтому она вылетела в 18:12:50 ... 

Tue Jan 15 17:51:54.391 [conn11125] end connection 127.0.0.1:53052 (1 connection now open)
Tue Jan 15 17:51:54.393 [initandlisten] connection accepted from 127.0.0.1:53054 #11126 (2 connections now open)
Tue Jan 15 17:51:54.408 [conn11126] end connection 127.0.0.1:53054 (1 connection now open)
Tue Jan 15 17:51:54.410 [initandlisten] connection accepted from 127.0.0.1:53056 #11127 (2 connections now open)
Wed Jan 16 04:33:04.994 [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
Wed Jan 16 04:33:04.994 [signalProcessingThread] now exiting
Wed Jan 16 04:33:04.994 dbexit:
Wed Jan 16 04:33:04.994 [signalProcessingThread] shutdown: going to close listening sockets...
Wed Jan 16 04:33:04.994 [signalProcessingThread] closing listening socket: 9
Wed Jan 16 04:33:04.994 [signalProcessingThread] closing listening socket: 10
Wed Jan 16 04:33:04.994 [signalProcessingThread] closing listening socket: 11
Wed Jan 16 04:33:04.994 [signalProcessingThread] removing socket file: /tmp/mongodb-27017.sock
Wed Jan 16 04:33:04.994 [signalProcessingThread] shutdown: going to flush diaglog...
Wed Jan 16 04:33:04.994 [signalProcessingThread] shutdown: going to close sockets...
Wed Jan 16 04:33:04.994 [signalProcessingThread] shutdown: waiting for fs preallocator...
Wed Jan 16 04:33:04.994 [signalProcessingThread] shutdown: lock for final commit...
Wed Jan 16 04:33:04.994 [signalProcessingThread] shutdown: final commit...
Wed Jan 16 04:33:04.995 [signalProcessingThread] shutdown: closing all files...
Wed Jan 16 04:33:04.995 [conn11127] end connection 127.0.0.1:53056 (1 connection now open)
Wed Jan 16 04:33:04.997 [signalProcessingThread] closeAllFiles() finished
Wed Jan 16 04:33:04.997 [signalProcessingThread] journalCleanup...
Wed Jan 16 04:33:04.997 [signalProcessingThread] removeJournalFiles
Wed Jan 16 04:33:05.053 [conn4] end connection 127.0.0.1:56470 (0 connections now open)
Wed Jan 16 04:33:05.223 [signalProcessingThread] shutdown: removing fs lock...
Wed Jan 16 04:33:05.224 dbexit: really exiting now


***** SERVER RESTARTED *****
      # Everything works fine from this point onwards

Сегодня 16 января, и все сообщения 16 января были зарегистрированы, когда я перезагружал raspberry pi, теперь программа работает совершенно нормально ... но эта проблема продолжает возникать, когда я оставляю ее работающей и проверяю на следующий день.

Мой вопрос: почему это происходит? Когда прекращается обслуживание монго? Почему я не могу перезапустить его с моей функцией? Кто-нибудь может объяснить, что можно вывести из логов? Может ли непредвиденное отключение питания вызвать запуск службы mongodb при запуске? Пожалуйста, помогите мне разобраться с тем, что может происходить и как я могу справиться с этим, я не хочу, чтобы моя программа зависала!

Извините за длинный пост, я могу предоставить любые дополнительные детали, которые вам требуются.

Спасибо, что прочитали.

РЕДАКТИРОВАТЬ: Просто хочу уточнить, откуда происходит ошибка AttributeError: Nonetype. Имейте в виду, что под коллекцией я имею в виду документ в базе данных. У меня есть функция с именем update_status_collection (): 

 def update_status_collection(the_update):
       try:
            document = get_database_collection(collection_name='status_collection')
            document.update(the_update)
       except Exception:
            database_logger = logging.getLogger('database_thread')
            database_logger.exception('Could not update_status_collection')
            start_mongo_service()
            update_status_collection(the_update)

Теперь по какой-то причине функция get_database_collection возвращает Nonetype в переменную документа, и именно здесь возникает исключение AttributeError, потому что вы не можете обновить Nonetype. Хотя мне любопытно, как Nonetype возвращается, когда get_database_collection () также рекурсивен ..... он должен вернуть None после того, как достигнет MaximumRecursionDepth, верно? Это то, что мне еще предстоит изучить.

ОБНОВЛЕНИЕ: Хорошо, я искал системные журналы, чтобы найти что-то подозрительное, и я думаю, что нашел точку Linux остановил Монго. Ниже приведены системные журналы для 15 января (/ var / log / syslog): 

Jan 15 12:12:07 raspberrypi systemd[1]: Stopping An object/document-oriented database...
Jan 15 12:12:08 raspberrypi systemd[1]: Stopped An object/document-oriented database.
Jan 15 12:12:08 raspberrypi rc.local[463]: [967] Failed to execute script __main__
Jan 15 12:12:11 raspberrypi systemd[1]: Started An object/document-oriented database.
Jan 15 12:12:11 raspberrypi mongod[2336]: all output going to: /var/log/mongodb/mongodb.log
Jan 15 12:14:22 raspberrypi systemd[1]: Stopped target Timers.
Jan 15 12:14:22 raspberrypi systemd[1]: Stopped Daily apt upgrade and clean activities.
Jan 15 12:14:22 raspberrypi systemd[1]: Stopped target Bluetooth.
Jan 15 12:14:22 raspberrypi systemd[1]: Stopped Daily apt download activities.
Jan 15 12:14:22 raspberrypi systemd[1]: Stopping User Manager for UID 1000...
Jan 15 12:14:22 raspberrypi systemd[1]: Stopped target System Time Synchronized.
Jan 15 12:14:22 raspberrypi vncserver-x11-serviced[453]: XIO:  fatal IO error 11 (Resource temporarily unavailable) on X server ":0"
Jan 15 12:14:22 raspberrypi vncserver-x11-serviced[453]:       after 14426 requests (14426 known processed) with 0 events remaining.
Jan 15 12:14:22 raspberrypi bluetoothd[524]: Terminating
Jan 15 12:14:22 raspberrypi systemd[1]: Stopping Bluetooth service...
Jan 15 12:14:22 raspberrypi watchdog[562]: stopping daemon (5.15)
Jan 15 12:14:22 raspberrypi systemd[1]: Stopping Disk Manager...
Jan 15 12:14:22 raspberrypi udisksd[883]: udisks daemon version 2.1.8 exiting
Jan 15 12:14:22 raspberrypi systemd[1]: Stopped target Sound Card.
Jan 15 12:14:22 raspberrypi bluetoothd[524]: Stopping SDP server
Jan 15 12:14:22 raspberrypi systemd[1]: Closed Load/Save RF Kill Switch Status /dev/rfkill Watch.
Jan 15 12:14:22 raspberrypi bluetoothd[524]: Exit
Jan 15 12:14:22 raspberrypi systemd[1]: Stopping watchdog daemon...
Jan 15 12:14:22 raspberrypi systemd[1]: Stopping Save/Restore Sound Card State...
Jan 15 12:14:22 raspberrypi systemd[1]: Unmounting RPC Pipe File System...
Jan 15 12:14:22 raspberrypi systemd[1]: Stopping Authorization Manager...
Jan 15 12:14:22 raspberrypi systemd[1]: Stopped Daily Cleanup of Temporary Directories.
Jan 15 12:14:22 raspberrypi systemd[1]: Stopping Session c1 of user pi.
Jan 15 12:14:22 raspberrypi systemd[1]: Stopped Getty on tty1.
Jan 15 12:14:22 raspberrypi vncserver-x11-serviced[453]: XIO:  fatal IO error 11 (Resource temporarily unavailable) on X server ":0"
Jan 15 12:14:28 raspberrypi systemd-modules-load[111]: Inserted module 'i2c_dev'
Jan 15 12:14:28 raspberrypi systemd[1]: Started Apply Kernel Variables.
Jan 15 12:14:28 raspberrypi fake-hwclock[112]: Tue 15 Jan 12:14:24 UTC 2019
Jan 15 12:14:28 raspberrypi systemd[1]: Time has been changed
Jan 15 12:14:28 raspberrypi systemd[1]: Started Restore / save the current clock.
Jan 15 12:14:28 raspberrypi systemd-fsck[113]: e2fsck 1.43.4 (31-Jan-2017)
Jan 15 12:14:28 raspberrypi systemd[1]: Started Create Static Device Nodes in /dev.
Jan 15 12:14:28 raspberrypi systemd[1]: Starting udev Kernel Device Manager...
Jan 15 12:14:28 raspberrypi systemd-fsck[113]: /dev/mmcblk0p2: clean, 137720/939744 files, 1384356/3809792 blocks
Jan 15 12:14:28 raspberrypi systemd[1]: Started File System Check on Root Device.
Jan 15 12:14:28 raspberrypi systemd[1]: Starting Remount Root and Kernel File Systems...
Jan 15 12:14:28 raspberrypi systemd[1]: Started Remount Root and Kernel File Systems.
Jan 15 12:14:28 raspberrypi systemd[1]: Starting Load/Save Random Seed...
Jan 15 12:14:28 raspberrypi systemd[1]: Starting udev Coldplug all Devices...
Jan 15 12:14:28 raspberrypi systemd[1]: Starting Flush Journal to Persistent Storage...
Jan 15 12:14:28 raspberrypi systemd[1]: Started Load/Save Random Seed.
Jan 15 12:14:28 raspberrypi systemd[1]: Started Flush Journal to Persistent Storage.
Jan 15 12:14:28 raspberrypi systemd[1]: Started Set the console keyboard layout.
Jan 15 12:14:28 raspberrypi systemd[1]: Reached target Local File Systems (Pre).
Jan 15 12:14:28 raspberrypi systemd[1]: Started udev Kernel Device Manager.
Jan 15 12:14:28 raspberrypi systemd[1]: Started udev Coldplug all Devices.
Jan 15 12:14:28 raspberrypi systemd[1]: Starting Show Plymouth Boot Screen...
Jan 15 12:14:28 raspberrypi systemd[1]: Found device /dev/serial1.
Jan 15 12:14:28 raspberrypi systemd[1]: Started Show Plymouth Boot Screen.
Jan 15 12:14:28 raspberrypi systemd[1]: Reached target Encrypted Volumes.
Jan 15 12:14:28 raspberrypi systemd[1]: Reached target Paths.
Jan 15 12:14:28 raspberrypi systemd[1]: Started Forward Password Requests to Plymouth Directory Watch.
Jan 15 12:14:28 raspberrypi mtp-probe: checking bus 1, device 3: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1"
Jan 15 12:14:28 raspberrypi mtp-probe: checking bus 1, device 4: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2"
Jan 15 12:14:28 raspberrypi mtp-probe: checking bus 1, device 5: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.4"
Jan 15 12:14:28 raspberrypi mtp-probe: bus: 1, device: 4 was not an MTP device
Jan 15 12:14:28 raspberrypi mtp-probe: bus: 1, device: 5 was not an MTP device
Jan 15 12:14:28 raspberrypi mtp-probe: bus: 1, device: 3 was not an MTP device
Jan 15 12:14:28 raspberrypi systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.
Jan 15 12:14:28 raspberrypi systemd[1]: Reached target Sound Card.
Jan 15 12:14:28 raspberrypi systemd[1]: Found device /dev/disk/by-partuuid/f143b93d-01.
Jan 15 12:14:28 raspberrypi systemd[1]: Starting File System Check on /dev/disk/by-partuuid/f143b93d-01...

Первые две строки останавливают базу данных, третья строка "Не удалось выполнить скрипт main " из моей программы! Но сразу после этого он перезапускает базу данных .... Может кто-то понять, что произошло? Кажется, многие службы были остановлены, а затем перезапущены ...

1 Ответ

0 голосов
/ 23 января 2019

Эта проблема теперь решена, когда при чтении моего датчика температуры на Raspberry Pi с использованием SPI spi.close () не вызывался должным образом, и в результате каждый spi.open () приводил к созданию нового файла spidev. открыт. Существует ограничение на количество файлов, которое может открыть один процесс, и этот предел был достигнут в моем случае примерно через 6-7 часов, после чего скрипт потерпел крах.

Также важно отметить, что надлежащее ведение журнала не было реализовано в этой области кода, и исключения не были должным образом перехвачены, поэтому исключение «OSError: Too many open files» не было перехвачено или зарегистрировано, что делало эту проблему очень загадочной.

Как только исключение было обнаружено, это было легко исправить, правильно добавив spi.close () в каждое место, где открывался spi.

Вы можете проверить, сколько файлов открыл ваш процесс, используя: 

lsof -p <pid_of_your_process>

Команда lsof не была установлена ​​по умолчанию в моем дистрибутиве Linux, поэтому я использовал: 

sudo apt install lsof

Теперь причина, по которой это связано с моими исключениями для соединения pymongo, заключается в том, что для создания соединения модуль pymongo вызывает open () для различных вещей, таких как сокеты и т. Д., Что, в свою очередь, открывает файл. Я предполагаю, что моя программа не смогла открыть эти файлы через шесть часов, потому что она уже достигла максимального количества файлов, которые она могла открыть, и поэтому вызвала исключения для pymongo.

Надеюсь, это кому-нибудь поможет!

...