search

OpenDroneMap / NodeMICMAC

A Lightweight REST API to Access MICMAC Photogrammetry and SFM Engine.
https://opendronemap.org/nodemicmac/
GNU General Public License v3.0
79 stars 21 forks source link

MicMac hangs at Uploading Images to Processing Node #31

Closed ChipwizBen closed 2 years ago

ChipwizBen commented 5 years ago

Happens maybe 9/10 times. Nothing in the console log. Completely default Docker install on CentOS 7, other than creating a user.

/var/log/messages:

Jun 20 22:42:03 proc-dev.nwk1.com journal: WARNING Session data corrupted
Jun 20 22:42:03 proc-dev.nwk1.com webodm.sh: #033[31mwebapp           |#033[0m WARNING Session data corrupted
Jun 20 22:42:04 proc-dev.nwk1.com journal: WARNING Session data corrupted
Jun 20 22:42:04 proc-dev.nwk1.com webodm.sh: #033[31mwebapp           |#033[0m WARNING Session data corrupted
Jun 20 22:42:06 proc-dev.nwk1.com journal: WARNING Session data corrupted
Jun 20 22:42:06 proc-dev.nwk1.com webodm.sh: #033[31mwebapp           |#033[0m WARNING Session data corrupted
Jun 20 22:42:17 proc-dev.nwk1.com qemu-ga: info: guest-ping called
Jun 20 22:42:25 proc-dev.nwk1.com chronyd[5472]: Selected source 103.242.68.68
Jun 20 22:42:30 proc-dev.nwk1.com qemu-ga: info: guest-ping called
Jun 20 22:42:44 proc-dev.nwk1.com qemu-ga: info: guest-ping called
Jun 20 22:42:58 proc-dev.nwk1.com qemu-ga: info: guest-ping called
Jun 20 22:43:13 proc-dev.nwk1.com qemu-ga: info: guest-ping called
Jun 20 22:43:29 proc-dev.nwk1.com qemu-ga: info: guest-ping called
Jun 20 22:45:31 proc-dev.nwk1.com qemu-ga: info: guest-ping called
Jun 20 22:45:42 proc-dev.nwk1.com qemu-ga: info: guest-ping called
Jun 20 22:45:55 proc-dev.nwk1.com qemu-ga: info: guest-ping called
Jun 20 22:46:10 proc-dev.nwk1.com qemu-ga: info: guest-ping called
Jun 20 22:46:25 proc-dev.nwk1.com qemu-ga: info: guest-ping called
Jun 20 22:46:27 proc-dev.nwk1.com journal: INFO Task c821281e-c9f4-47a9-9d11-bda9fd3e680b has already been deleted.
Jun 20 22:46:27 proc-dev.nwk1.com journal: [2019-06-20 10:46:27,099: INFO/ForkPoolWorker-4] worker.tasks.process_task[e74a9a09-4606-45e5-9c81-ba6b6e636f8b]: Task c821281e-c9f4-47a9-9d11-bda9fd3e680b has already been deleted.
Jun 20 22:46:27 proc-dev.nwk1.com webodm.sh: #033[35mworker           |#033[0m INFO Task c821281e-c9f4-47a9-9d11-bda9fd3e680b has already been deleted.
Jun 20 22:46:27 proc-dev.nwk1.com webodm.sh: #033[35mworker           |#033[0m [2019-06-20 10:46:27,099: INFO/ForkPoolWorker-4] worker.tasks.process_task[e74a9a09-4606-45e5-9c81-ba6b6e636f8b]: Task c821281e-c9f4-47a9-9d11-bda9fd3e680b has already been deleted.
Jun 20 22:46:30 proc-dev.nwk1.com journal: INFO Processing... Task [WaiCol] (c821281e-c9f4-47a9-9d11-bda9fd3e680b)
Jun 20 22:46:30 proc-dev.nwk1.com journal: [2019-06-20 10:46:30,267: INFO/ForkPoolWorker-4] worker.tasks.process_task[457810f3-9964-4fd1-a571-81c22bfcc3f5]: Processing... Task [WaiCol] (c821281e-c9f4-47a9-9d11-bda9fd3e680b)
Jun 20 22:46:30 proc-dev.nwk1.com webodm.sh: #033[35mworker           |#033[0m INFO Processing... Task [WaiCol] (c821281e-c9f4-47a9-9d11-bda9fd3e680b)
Jun 20 22:46:30 proc-dev.nwk1.com webodm.sh: #033[35mworker           |#033[0m [2019-06-20 10:46:30,267: INFO/ForkPoolWorker-4] worker.tasks.process_task[457810f3-9964-4fd1-a571-81c22bfcc3f5]: Processing... Task [WaiCol] (c821281e-c9f4-47a9-9d11-bda9fd3e680b)
Jun 20 22:46:31 proc-dev.nwk1.com journal: 1:M 20 Jun 2019 10:46:31.060 * 100 changes in 300 seconds. Saving...
Jun 20 22:46:31 proc-dev.nwk1.com webodm.sh: #033[36mbroker           |#033[0m 1:M 20 Jun 2019 10:46:31.060 * 100 changes in 300 seconds. Saving...
Jun 20 22:46:31 proc-dev.nwk1.com journal: 1:M 20 Jun 2019 10:46:31.063 * Background saving started by pid 19
Jun 20 22:46:31 proc-dev.nwk1.com webodm.sh: #033[36mbroker           |#033[0m 1:M 20 Jun 2019 10:46:31.063 * Background saving started by pid 19
Jun 20 22:46:31 proc-dev.nwk1.com journal: 19:C 20 Jun 2019 10:46:31.271 * DB saved on disk
Jun 20 22:46:31 proc-dev.nwk1.com webodm.sh: #033[36mbroker           |#033[0m 19:C 20 Jun 2019 10:46:31.271 * DB saved on disk
Jun 20 22:46:31 proc-dev.nwk1.com journal: 19:C 20 Jun 2019 10:46:31.272 * RDB: 6 MB of memory used by copy-on-write
Jun 20 22:46:31 proc-dev.nwk1.com webodm.sh: #033[36mbroker           |#033[0m 19:C 20 Jun 2019 10:46:31.272 * RDB: 6 MB of memory used by copy-on-write
Jun 20 22:46:31 proc-dev.nwk1.com journal: 1:M 20 Jun 2019 10:46:31.364 * Background saving terminated with success
Jun 20 22:46:31 proc-dev.nwk1.com webodm.sh: #033[36mbroker           |#033[0m 1:M 20 Jun 2019 10:46:31.364 * Background saving terminated with success

Node details (shows as online):

Hostname node-micmac-1
Port 3000
API Version 1.5.1
Engine micmac
Engine Version 0.0.1
Queue Count 0
Max Images Limit None
Label None
Last Refreshed 0 minutes ago (20 Jun 2019, 10:51 a.m.)
dronemapper-io commented 5 years ago

Thanks. Can you provide some more details on the number of images/etc? Did you try uploading the same image set directly to the NodeMICMAC API at port 3000? Did that work?

pierotofy commented 5 years ago

This is probably a problem with WebODM. Make sure to update to the latest version (1.1.0) and try again, since we fixed some race conditions bug since.

ChipwizBen commented 5 years ago

Updated to: App Version: 1.1.0

Sadly the problem still exists, even with a brand new project and dataset.

ChipwizBen commented 5 years ago

Well, this is interesting. Had a scoot through /var/log/messages and found this:

Jun 28 19:54:54 proc-dev.nwk1.com webodm.sh: #033[35mworker           |#033[0m
Jun 28 19:54:54 proc-dev.nwk1.com journal:  File "/usr/local/lib/python3.6/site-packages/pyodm/api.py", line 378, in create_task
Jun 28 19:54:54 proc-dev.nwk1.com journal:    raise nonloc.error
Jun 28 19:54:54 proc-dev.nwk1.com journal:  File "/usr/local/lib/python3.6/site-packages/pyodm/api.py", line 299, in worker
Jun 28 19:54:54 proc-dev.nwk1.com journal:    'images': [(os.path.basename(file), read_file(file), (mimetypes.guess_type(file)[0] or "image/jpg"))]
Jun 28 19:54:54 proc-dev.nwk1.com journal:  File "/usr/local/lib/python3.6/site-packages/pyodm/api.py", line 281, in read_file
Jun 28 19:54:54 proc-dev.nwk1.com journal:    with open(file_path, 'rb') as f:
Jun 28 19:54:54 proc-dev.nwk1.com journal: PermissionError: [Errno 13] Permission denied: '/webodm/app/media/project/13/task/7af86ef2-346b-4657-b9bc-da6cbe724e0a/1CD26242_987A_11E9_8009_064DA8AAA1DE.jpg'
Jun 28 19:54:54 proc-dev.nwk1.com journal: 
Jun 28 19:54:54 proc-dev.nwk1.com journal: [2019-06-28 07:54:54,653: ERROR/ForkPoolWorker-8] worker.tasks.process_task[4ae2d0ec-4813-462f-9ff5-d775aa70f777]: Uncaught error! This is potentially bad. Please report it to http://github.com/OpenDroneMap/WebODM/issues: [Errno 13] Permission denied: '/webodm/app/media/project/13/task/7af86ef2-346b-4657-b9bc-da6cbe724e0a/1CD26242_987A_11E9_8009_064DA8AAA1DE.jpg' Traceback (most recent call last):
Jun 28 19:54:54 proc-dev.nwk1.com journal:  File "/webodm/worker/tasks.py", line 103, in process_task
Jun 28 19:54:54 proc-dev.nwk1.com journal:    task.process()
Jun 28 19:54:54 proc-dev.nwk1.com journal:  File "/webodm/app/models/task.py", line 457, in process
Jun 28 19:54:54 proc-dev.nwk1.com journal:    uuid = self.processing_node.process_new_task(images, self.name, self.options, callback)
Jun 28 19:54:54 proc-dev.nwk1.com journal:  File "/webodm/nodeodm/models.py", line 119, in process_new_task
Jun 28 19:54:54 proc-dev.nwk1.com journal:    task = api_client.create_task(images, opts, name, progress_callback)
Jun 28 19:54:54 proc-dev.nwk1.com journal:  File "/usr/local/lib/python3.6/site-packages/pyodm/api.py", line 378, in create_task
Jun 28 19:54:54 proc-dev.nwk1.com journal:    raise nonloc.error
Jun 28 19:54:54 proc-dev.nwk1.com journal:  File "/usr/local/lib/python3.6/site-packages/pyodm/api.py", line 299, in worker
Jun 28 19:54:54 proc-dev.nwk1.com journal:    'images': [(os.path.basename(file), read_file(file), (mimetypes.guess_type(file)[0] or "image/jpg"))]
Jun 28 19:54:54 proc-dev.nwk1.com journal:  File "/usr/local/lib/python3.6/site-packages/pyodm/api.py", line 281, in read_file
Jun 28 19:54:54 proc-dev.nwk1.com journal:    with open(file_path, 'rb') as f:
Jun 28 19:54:54 proc-dev.nwk1.com journal: PermissionError: [Errno 13] Permission denied: '/webodm/app/media/project/13/task/7af86ef2-346b-4657-b9bc-da6cbe724e0a/1CD26242_987A_11E9_8009_064DA8AAA1DE.jpg'
Jun 28 19:54:54 proc-dev.nwk1.com journal: 
[root@proc-dev ~]# ll /webodm
ls: cannot access /webodm: No such file or directory

This is a Docker install, it has never been a native install, so it's puzzling as to why it's looking for that directory. This doesn't explain why some begin processing though. Very strange.

ChipwizBen commented 5 years ago

For what it's worth, triggering an update fixes these permission issues on uploaded datasets. Uploading new sets still exhibit the same problem. I'm guessing that the process that saves the uploaded files is saving the files with permissions that the next part of the process (upload to node) isn't able to read and running the update does a global permission fix. Have been too busy to dig into it lately but will do if I get some time soon.

dronemapper-io commented 5 years ago

Looks like @pierotofy is aware and on it. It seems like a webodm or webodm vs nodemicmac integration issue. Thanks

kikislater commented 2 years ago

Reopen if still an issue