search

bluerobotics / BlueOS

The open source platform for ROV, USV, robotic system operation, development, and expansion.
https://blueos.cloud/docs/
Other
151 stars 73 forks source link

bug: empty files in files/ardupilot_logs/logs #2041

Open clydemcqueen opened 1 year ago

clydemcqueen commented 1 year ago

Bug description

I'm not sure what these files should contain, but they are empty.

image

Steps to reproduce

I'm running BlueOS on a Pi3 connected to a Pixhawk (on the bench).

BlueOS Version: tags/1.1.0-beta.28-0-g2df6ae03 Bootstrap Version: 1.0.1 Build: 8/12/2023, 8:51:38 PM By Blue Robotics

Board name: Pixhawk1 Manufacturer: ArduPilot Mavlink platform: Pixhawk1 Firmware version: 4.1.0 (STABLE) Vehicle type: Submarine Path: /dev/ttyACM0

Primary pain point(s)

No response

Prerequisites

patrickelectric commented 1 year ago

Hi @clydemcqueen, it appears to be a bug of ArduPilot where it's creating log files without a log to write, since log is only done when the vehicle is armed (based on the default parameter). Do you have non empty logs ? Can you confirm it only happens when you don't arm the vehicle ?

clydemcqueen commented 1 year ago

Ah, these files should be the dataflash logs? I'm running BlueOS + Pixhawk, so I'm not sure what should happen.

I just enabled LOG_DISARMED (via QGC), armed / disarmed a few times (via QGC), restarted the autopilot, restarted the core container, etc.

I'm now seeing 10 DF logs in QGC, and the most recent log is 13MB and growing.

I'm now seeing 10 files in home > ardupilot_logs > logs, still all 0 bytes.

clydemcqueen commented 1 year ago

Here is the output from home > system_log > ardupilot-manager > logfile_08_25_2023_15:03:18.log:

2023-08-25 15:03:18.669 | INFO     | __main__:<module>:48 - Starting ArduPilot Manager.
2023-08-25 15:03:18.752 | INFO     | ArduPilotManager:__init__:52 - Loaded settings from /root/.config/ardupilot-manager/settings.json.
2023-08-25 15:03:18.756 | DEBUG    | ArduPilotManager:__init__:53 - {'endpoints': [{'__pydantic_initialised__': True, 'argument': 14550, 'connection_type': 'udpin', 'enabled': True, 'name': 'GCS Server Link', 'overwrite_settings': False, 'owner': 'ardupilot-manager', 'persistent': True, 'place': '0.0.0.0', 'protected': False}, {'__pydantic_initialised__': True, 'argument': 14000, 'connection_type': 'udpout', 'enabled': True, 'name': 'MAVLink2Rest', 'overwrite_settings': False, 'owner': 'ardupilot-manager', 'persistent': True, 'place': '127.0.0.1', 'protected': True}, {'__pydantic_initialised__': True, 'argument': 14551, 'connection_type': 'udpout', 'enabled': True, 'name': 'My client endpoint', 'overwrite_settings': False, 'owner': 'User', 'persistent': True, 'place': '192.168.2.1', 'protected': False}, {'__pydantic_initialised__': True, 'argument': 14550, 'connection_type': 'udpout', 'enabled': True, 'name': 'GCS Client Link', 'overwrite_settings': False, 'owner': 'ardupilot-manager', 'persistent': True, 'place': '192.168.2.1', 'protected': False}, {'__pydantic_initialised__': True, 'argument': 14551, 'connection_type': 'udpin', 'enabled': True, 'name': 'My server endpoint', 'overwrite_settings': False, 'owner': 'User', 'persistent': True, 'place': '0.0.0.0', 'protected': False}, {'__pydantic_initialised__': True, 'argument': 14660, 'connection_type': 'udpin', 'enabled': True, 'name': 'Ping360 Heading', 'overwrite_settings': False, 'owner': 'ardupilot-manager', 'persistent': True, 'place': '0.0.0.0', 'protected': True}, {'__pydantic_initialised__': True, 'argument': 5777, 'connection_type': 'tcpin', 'enabled': True, 'name': 'Internal Link', 'overwrite_settings': True, 'owner': 'ardupilot-manager', 'persistent': True, 'place': '127.0.0.1', 'protected': True}], 'preferred_board': {'manufacturer': 'ArduPilot', 'name': 'Pixhawk1', 'platform': 'Pixhawk1'}}
2023-08-25 15:03:18.805 | WARNING  | ArduPilotManager:remove_old_logs:84 - Failed to remove logs: [Errno 2] No such file or directory: '/root/.config/ardupilot-manager/firmware/logs'
2023-08-25 15:03:19.076 | DEBUG    | asyncio.selector_events:__init__:54 - Using selector: EpollSelector
2023-08-25 15:03:19.081 | DEBUG    | flight_controller_detector.Detector:detect_linux_board:50 - Trying to detect Linux board.
2023-08-25 15:03:19.088 | DEBUG    | flight_controller_detector.Detector:detect_linux_board:57 - No Linux board detected.
2023-08-25 15:03:19.154 | WARNING  | ArduPilotManager:start_ardupilot:473 - More than a single board detected: [FlightController(name='Pixhawk1', manufacturer='ArduPilot', platform=<Platform.Pixhawk1: 'Pixhawk1'>, path='/dev/ttyACM0', flags=[]), FlightController(name='SITL', manufacturer='ArduPilot Team', platform=<Platform.SITL: 'SITL_arm_linux_gnueabihf'>, path=None, flags=[])]
2023-08-25 15:03:19.158 | DEBUG    | ArduPilotManager:get_board_to_be_used:388 - Preferred flight-controller is Pixhawk1.
2023-08-25 15:03:19.161 | INFO     | ArduPilotManager:start_ardupilot:476 - Using Pixhawk1 flight-controller.
2023-08-25 15:03:19.176 | DEBUG    | mavlink_proxy.AbstractRouter:start:90 - Calling router using following command: '/usr/bin/mavlink-routerd /dev/ttyACM0:115200 0.0.0.0:14550 0.0.0.0:14660 0.0.0.0:14551 --endpoint 192.168.2.1:14551 --endpoint 127.0.0.1:14000 --endpoint 192.168.2.1:14550 --tcp-port 5777 -l /root/.config/ardupilot-manager/logs'.
2023-08-25 15:03:21.767 | INFO     | uvicorn.server:serve:64 - Started server process [94]
2023-08-25 15:03:21.778 | INFO     | uvicorn.lifespan.on:startup:26 - Waiting for application startup.
2023-08-25 15:03:21.785 | INFO     | uvicorn.lifespan.on:startup:38 - Application startup complete.
2023-08-25 15:03:21.816 | INFO     | uvicorn.server:_log_started_message:199 - Uvicorn running on http://0.0.0.0:8000 (Press CTRL+C to quit)
2023-08-25 15:03:24.885 | INFO     | uvicorn.protocols.http.h11_impl:send:461 - 127.0.0.1:40424 - "GET / HTTP/1.1" 200
2023-08-25 15:03:25.032 | INFO     | uvicorn.protocols.http.h11_impl:send:461 - 127.0.0.1:40432 - "GET /register_service HTTP/1.1" 404
2023-08-25 15:03:25.093 | INFO     | uvicorn.protocols.http.h11_impl:send:461 - 127.0.0.1:40434 - "GET /docs HTTP/1.1" 200
2023-08-25 15:03:25.149 | INFO     | uvicorn.protocols.http.h11_impl:send:461 - 127.0.0.1:40436 - "GET /docs.json HTTP/1.1" 404
2023-08-25 15:03:25.182 | INFO     | uvicorn.protocols.http.h11_impl:send:461 - 127.0.0.1:40438 - "GET /openapi.json HTTP/1.1" 200
2023-08-25 15:03:25.202 | INFO     | uvicorn.protocols.http.h11_impl:send:461 - 127.0.0.1:40440 - "GET /v1.0/docs HTTP/1.1" 200
2023-08-25 15:03:25.601 | INFO     | uvicorn.protocols.http.h11_impl:send:461 - 127.0.0.1:40442 - "GET /v1.0/openapi.json HTTP/1.1" 200
2023-08-25 15:03:25.629 | INFO     | uvicorn.protocols.http.h11_impl:send:461 - 127.0.0.1:40446 - "GET /swagger.json HTTP/1.1" 404
2023-08-25 15:03:28.230 | INFO     | uvicorn.protocols.http.h11_impl:send:461 - 127.0.0.1:40562 - "GET /v1.0/firmware_info HTTP/1.0" 200
2023-08-25 15:03:28.866 | INFO     | uvicorn.protocols.http.h11_impl:send:461 - 127.0.0.1:40478 - "GET /v1.0/vehicle_type HTTP/1.0" 200
2023-08-25 15:03:29.962 | INFO     | uvicorn.protocols.http.h11_impl:send:461 - 127.0.0.1:40584 - "GET /v1.0/vehicle_type HTTP/1.0" 200
2023-08-25 15:03:31.696 | ERROR    | asyncio.base_events:default_exception_handler:1753 - Task exception was never retrieved
future: <Task finished name='Task-2' coro=<ArduPilotManager.auto_restart_ardupilot() done, defined at /home/pi/services/ardupilot_manager/ArduPilotManager.py:86> exception=psutil.NoSuchProcess process no longer exists (pid=403)>
Traceback (most recent call last):

  File "/usr/local/lib/python3.9/site-packages/psutil-5.7.2-py3.9-linux-armv7l.egg/psutil/_pslinux.py", line 1515, in wrapper
    return fun(self, *args, **kwargs)
           │   │      │       └ {}
           │   │      └ ()
           │   └ <psutil._pslinux.Process object at 0x754e2438>
           └ <function Process.cmdline at 0x75cd2d60>
  File "/usr/local/lib/python3.9/site-packages/psutil-5.7.2-py3.9-linux-armv7l.egg/psutil/_pslinux.py", line 1635, in cmdline
    with open_text("%s/%s/cmdline" % (self._procfs_path, self.pid)) as f:
         │                            │    │             │    └ <member 'pid' of 'Process' objects>
         │                            │    │             └ <psutil._pslinux.Process object at 0x754e2438>
         │                            │    └ <member '_procfs_path' of 'Process' objects>
         │                            └ <psutil._pslinux.Process object at 0x754e2438>
         └ <function open_text at 0x75cb6970>
  File "/usr/local/lib/python3.9/site-packages/psutil-5.7.2-py3.9-linux-armv7l.egg/psutil/_common.py", line 727, in open_text
    return open(fname, "rt", **kwargs)
                │              └ {'encoding': 'utf-8', 'errors': 'surrogateescape'}
                └ '/proc/403/cmdline'

FileNotFoundError: [Errno 2] No such file or directory: '/proc/403/cmdline'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):

> File "/home/pi/services/ardupilot_manager/ArduPilotManager.py", line 91, in auto_restart_ardupilot
    ) or len(self.running_ardupilot_processes()) == 0
             │    └ <function ArduPilotManager.running_ardupilot_processes at 0x7557e1d8>
             └ <ArduPilotManager.ArduPilotManager object at 0x7556e520>

  File "/home/pi/services/ardupilot_manager/ArduPilotManager.py", line 417, in running_ardupilot_processes
    return list(filter(is_ardupilot_process, psutil.process_iter()))
                       │                     │      └ <function process_iter at 0x75cd84f0>
                       │                     └ <module 'psutil' from '/usr/local/lib/python3.9/site-packages/psutil-5.7.2-py3.9-linux-armv7l.egg/psutil/__init__.py'>
                       └ <function ArduPilotManager.running_ardupilot_processes.<locals>.is_ardupilot_process at 0x74c754f0>

  File "/home/pi/services/ardupilot_manager/ArduPilotManager.py", line 413, in is_ardupilot_process
    if str(firmware_path) in " ".join(process.cmdline()):
           │                          │       └ <function Process.cmdline at 0x75cd6418>
           │                          └ psutil.Process(pid=403, status='terminated', started='15:03:27')
           └ PosixPath('/root/.config/ardupilot-manager/firmware/ardupilot_sitl_arm_linux_gnueabihf')

  File "/usr/local/lib/python3.9/site-packages/psutil-5.7.2-py3.9-linux-armv7l.egg/psutil/__init__.py", line 694, in cmdline
    return self._proc.cmdline()
           │    │     └ <function Process.cmdline at 0x75cd2da8>
           │    └ <psutil._pslinux.Process object at 0x754e2438>
           └ psutil.Process(pid=403, status='terminated', started='15:03:27')
  File "/usr/local/lib/python3.9/site-packages/psutil-5.7.2-py3.9-linux-armv7l.egg/psutil/_pslinux.py", line 1522, in wrapper
    raise NoSuchProcess(self.pid, self._name)
          │             │    │    │    └ <member '_name' of 'Process' objects>
          │             │    │    └ <psutil._pslinux.Process object at 0x754e2438>
          │             │    └ <member 'pid' of 'Process' objects>
          │             └ <psutil._pslinux.Process object at 0x754e2438>
          └ <class 'psutil.NoSuchProcess'>

psutil.NoSuchProcess: psutil.NoSuchProcess process no longer exists (pid=403)
Williangalvani commented 1 year ago

These are actually logs created by mavlink-router. it should create tlog files correctly when LOG_BACKEND includes the MAVLINK flag

Williangalvani commented 1 year ago

probably related to https://github.com/mavlink-router/mavlink-router/issues/282