search

PX4 / flight_review

web application for flight log analysis & review
https://logs.px4.io/
BSD 3-Clause "New" or "Revised" License
202 stars 195 forks source link

HTTP Error 500 (again) #217

Closed Decclo closed 3 years ago

Decclo commented 3 years ago

Going to logs.px4.io and uploading an .ulg file will result in "HTTP Error 500 ".

The file can be visualized just fine by running it locally with ./serve.py -f file.ulg, but using ./serve.py --show and uploading the file to the presented browser window will also result in the same "HTTP Error 500". Using ./serve.py --show will result in the following output from the terminal:

(flightreview) locus@DX68:~/Git/flight_review/app$ ./serve.py --show
Error when handling POST data <class 'KeyError'> 'email'
ERROR:tornado.access:500 POST /upload (127.0.0.1) 54.56ms

Feeding the file into ulog_info file.ulg results in the following output:

Logging start time: 0:09:39, duration: 0:13:11
Dropouts: count: 66, total duration: 13.2 s, max: 949 ms, mean: 200 ms
SW Version: v1.10.1
Info Messages:
 sys_mcu: STM32F42x, rev. 3
 sys_name: PX4
 sys_os_name: NuttX
 sys_os_ver: 427238133be2b0ecd068a11e886ee8fdbc31f6dc
 sys_os_ver_release: 119341311
 sys_toolchain: GNU GCC
 sys_toolchain_ver: 7.2.1 20170904 (release) [ARM/embedded-7-branch revision 255204]
 sys_uuid: 000100000000313538333036510c004a0022
 time_ref_utc: 0
 ver_hw: PX4_FMU_V3
 ver_hw_subtype: V30
 ver_sw: e0f016c2b3db160284bbaaadaf70bef84592d81e
 ver_sw_release: 17433087
 ver_vendor_sw_release: 255
Info Multiple Messages: [perf_counter_postflight: 1], [perf_counter_preflight: 1], [perf_top_postflight: 1], [perf_top_preflight: 1]

Name (multi id, message size in bytes)    number of data points, total bytes
 actuator_controls_0 (0, 48)                 7615     365520
 actuator_outputs (0, 76)                    7607     578132
 actuator_outputs (1, 76)                    7602     577752
 battery_status (0, 83)                      1549     128567
 cpuload (0, 16)                              777      12432
 ekf2_innovations (0, 164)                   3843     630252
 ekf2_timestamps (0, 22)                   174935    3848570
 ekf_gps_drift (0, 21)                         30        630
 estimator_status (0, 271)                   3844    1041724
 home_position (0, 47)                          2         94
 input_rc (0, 69)                            3839     264891
 manual_control_setpoint (0, 67)             3842     257414
 mission_result (0, 32)                        84       2688
 position_setpoint_triplet (0, 344)            84      28896
 radio_status (0, 17)                           1         17
 rate_ctrl_status (0, 24)                    3839      92136
 safety (0, 12)                               776       9312
 sensor_combined (0, 44)                   176934    7785096
 sensor_preflight (0, 20)                       6        120
 sensor_selection (0, 24)                       1         24
 system_power (0, 23)                        1548      35604
 telemetry_status (0, 47)                     858      40326
 trajectory_setpoint (0, 76)                 3834     291384
 vehicle_air_data (0, 24)                   57756    1386144
 vehicle_angular_velocity (0, 28)           35166     984648
 vehicle_attitude (0, 41)                   14838     608358
 vehicle_attitude_setpoint (0, 58)           7594     440452
 vehicle_command (0, 52)                       23       1196
 vehicle_global_position (0, 68)             3844     261392
 vehicle_gps_position (0, 99)                3890     385110
 vehicle_land_detected (0, 17)                795      13515
 vehicle_local_position (0, 155)             7606    1178930
 vehicle_local_position_setpoint (0, 76)     7582     576232
 vehicle_magnetometer (0, 20)               35383     707660
 vehicle_rates_setpoint (0, 32)             35113    1123616
 vehicle_status (0, 52)                       800      41600
 vehicle_status_flags (0, 39)                 800      31200

A similar problem has been reported 4 years ago here.

The code I've used for testing was the master at the time of writing this report.

The log file does not look corrupt to my untrained eye, but I might very well be wrong. Though, this problem does occur to all logs I've tried, including some logs from last year that I'm positive have worked before.

I've tried running the code to see whether I could find any useful information, but as you might have noticed I'm at my wits end. I can analyze the logs using ./serve.py -f file.ulg just fine, but I have a sneaking suspicion that I might not be the only one who currently has problems using logs.px4.io.

bkueng commented 3 years ago

Error when handling POST data <class 'KeyError'> 'email'

Looks like a problem with the request/handling of the input data. Can you follow that error, or send me the exact form inputs + ulog (via email is fine if you don't want it public).

Decclo commented 3 years ago

I tried to look into the error you mentioned before posting here, but only came to the conclusion that it was a problem with 'Tornado', either because of a bad log, some problem in flightreview, or a problem with Tornado itself.

I sadly haven't gotten farther than that yet, but the next step for me would be to read up on what 'Tornado' is and how it works.

I assume 'form inputs' refer to how I upload the file, please correct me if I've got it wrong:

  1. Either go to logs.px.io or run ./serve --show and wait for the webpage to open (they both seem to give the same error on the webpage).
  2. Press 'Choose File...' and navigate to relevant log file. In my case /home/locus/Documents/flight_review_issue217/log_new.ulg
  3. The log file will appear in the 'ULog File' box as 'log_new.ulg'.
  4. Press 'Upload' while leaving all other boxes empty.
  5. Receive 'HTTP Error 500 ' webpage.

Alternatively:

  1. Either go to logs.px.io or run ./serve --show and wait for the webpage to open (they both seem to give the same error on the webpage).
  2. Press 'Choose File...' and navigate to relevant log file. In my case /home/locus/Documents/flight_review_issue217/log_new.ulg
  3. The log file will appear in the 'ULog File' box as 'log_new.ulg'.
  4. Enter 'Description', 'Additional Feedback', and 'E-Mail'
  5. Press 'Upload'.
  6. Receive 'HTTP Error 500 ' webpage.

I'm attaching a the log that I'm having problems with, together with the older log I used to test whether the issue only applies to my new logs.

Furthermore, for consistency I'm including the a log of my terminal Terminal_log.txt. I have not changed the 'config_default.ini'. Note that I'm using an Anaconda environment with Python 3.6, as Python 3.9.5 seems to produce a dependency error, possibly with scipy version 1.3.3 (not important, just a note).

bkueng commented 3 years ago

Ah so you didn't enter any email? Just uploading these logs works fine for me.

You can just do a raise e in https://github.com/PX4/flight_review/blob/master/app/tornado_handlers/upload.py#L312, then you should get the original error.

Decclo commented 3 years ago

Exchanging raise CustomHTTPError(500) from e with raise e does indeed point towards it being the E-Mail somehow not being read correctly. I've tried both with and without E-Mail, but seem to get the same error.

When commenting out the E-Mail part (line 120 and 154 in the document you mentioned) I get an error that looks like it somehow had problems saving/reading the uploaded file:

(flightreview) locus@DX65:~/GitHub/flight_review/app$ ./serve.py --show
WARNING:tornado.access:404 GET /favicon.ico (127.0.0.1) 0.38ms
Moving uploaded file to /home/locus/GitHub/flight_review/app/plot_app/../../data/log_files/751a90c3-38cb-4dbc-a037-74b5ec809027.ulg
Error when handling POST data <class 'FileNotFoundError'> [Errno 2] No such file or directory: '/home/locus/GitHub/flight_review/app/plot_app/../../data/log_files/751a90c3-38cb-4dbc-a037-74b5ec809027.ulg'
ERROR:tornado.application:Uncaught exception POST /upload (127.0.0.1)
HTTPServerRequest(protocol='http', host='localhost:5006', method='POST', uri='/upload', version='HTTP/1.1', remote_ip='127.0.0.1')
Traceback (most recent call last):
  File "/home/locus/anaconda3/envs/flightreview/lib/python3.6/shutil.py", line 550, in move
    os.rename(src, real_dst)
FileNotFoundError: [Errno 2] No such file or directory: '/tmp/tmpc30fe7vf' -> '/home/locus/GitHub/flight_review/app/plot_app/../../data/log_files/751a90c3-38cb-4dbc-a037-74b5ec809027.ulg'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/locus/anaconda3/envs/flightreview/lib/python3.6/site-packages/tornado/web.py", line 1702, in _execute
    result = method(*self.path_args, **self.path_kwargs)
  File "/home/locus/GitHub/flight_review/app/tornado_handlers/upload.py", line 313, in post
    raise e
  File "/home/locus/GitHub/flight_review/app/tornado_handlers/upload.py", line 190, in post
    file_obj.move(new_file_name)
  File "/home/locus/GitHub/flight_review/app/tornado_handlers/multipart_streamer.py", line 178, in move
    shutil.move(self.f_out.name, file_path)
  File "/home/locus/anaconda3/envs/flightreview/lib/python3.6/shutil.py", line 564, in move
    copy_function(src, real_dst)
  File "/home/locus/anaconda3/envs/flightreview/lib/python3.6/shutil.py", line 263, in copy2
    copyfile(src, dst, follow_symlinks=follow_symlinks)
  File "/home/locus/anaconda3/envs/flightreview/lib/python3.6/shutil.py", line 121, in copyfile
    with open(dst, 'wb') as fdst:
FileNotFoundError: [Errno 2] No such file or directory: '/home/locus/GitHub/flight_review/app/plot_app/../../data/log_files/751a90c3-38cb-4dbc-a037-74b5ec809027.ulg'
ERROR:tornado.access:500 POST /upload (127.0.0.1) 54.37ms

When going to the data directory, I do not see log_files directory. I have the feeling that this is where I should continue looking.

bkueng commented 3 years ago

Did you use the app/setup_db.py script?

Decclo commented 3 years ago

No, I had indeed missed the setup script, thank you for pointing it out.

Once the setup script has been run, I still get the email error. I've found that commenting out line 120 and inserting email = '' in its place removes the error and allows the log to be displayed properly.

I've made sure that the other fields do work by printing out form_data['description'].decode("utf-8") etc.. This seems to be specific to the email field for whatever reason. At last, I've made sure that the E-Mail field name when exploring the served site is indeed 'email', so I'm not sure why It does not want to read it.

I've setup the config_user.ini with smtpserver, sender, user_name, and password. Furthermore, Iv'e filled public_flightreport, and public_flightreport_bad. I've also once again made sure that the email error happens regardless whether I enter an email into the E-Mail field on the served website.

I'm pasting the error once more, as to make it easier to find without having to download files:

(flightreview) locus@DX65:~/GitHub/flight_review/app$ python serve.py --show
Error when handling POST data <class 'KeyError'> 'email'
ERROR:tornado.application:Uncaught exception POST /upload (127.0.0.1)
HTTPServerRequest(protocol='http', host='localhost:5006', method='POST', uri='/upload', version='HTTP/1.1', remote_ip='127.0.0.1')
Traceback (most recent call last):
  File "/home/locus/anaconda3/envs/flightreview/lib/python3.6/site-packages/tornado/web.py", line 1702, in _execute
    result = method(*self.path_args, **self.path_kwargs)
  File "/home/locus/GitHub/flight_review/app/tornado_handlers/upload.py", line 314, in post
    raise e
  File "/home/locus/GitHub/flight_review/app/tornado_handlers/upload.py", line 120, in post
    email = form_data['email'].decode("utf-8")
KeyError: 'email'
ERROR:tornado.access:500 POST /upload (127.0.0.1) 8.78ms
bkueng commented 3 years ago

Points to a problem in MultiPartStreamer then. Which browser do you use?

Decclo commented 3 years ago

That was it, how stupid of me to not check the browser as the first thing. This also explains why it happened on all of my computers simultaneously, since I synchronize my browser settings.

I'm using Firefox 89.0 (64-bit) for Linux. Both Firefox and Chromium work just as expected when using private windows. It turns out that the problem is caused by Firefox Relay. Disabling this add-on (or simply unticking "Show Relay Icon in email fields on websites") makes flightreview load as expected. I've tested this both with logs.px4.io and a selfhosted instance.

I imagine this also explains why it was the E-Mail field causing the error, as Firefox Relay helps handle E-Mails. It's a little weird since I thought that the little icon that the add-on produces in E-Mail fields was purely for convenience and wasn't manipulating field unless explicitly told to do so, but I guess this is not the case. I wonder why this is not a problem on any other sites I frequent, but I guess there are reasons for this which go over my head.

This fixes the problem, I'll go file a bug report to Firefox Relay that the add-on can cause errors on some sites.

Thank you for the assistance in fixing this problem of mine. I'll leave the issue open for you to close.

bkueng commented 3 years ago

Makes sense. That behavior is indeed surprising.