#2303 Invalid upload attempt provides misleading info
Closed: Fixed 2 years ago by praiskup. Opened 2 years ago by praiskup.

$ copr --debug build vim-fugitive-gitlab /home/praiskup/rh/packages/vim-fugitive-gitlab/vim-fugitive-gitlab-0~20220701gitb73a8e-1.fc36.src.rpm
#  Debug log enabled  #
[17:27:30] {/usr/lib/python3.10/site-packages/filelock/_api.py:153} DEBUG - Attempting to acquire lock 140276775771568 on /home/praiskup/.cache/copr/copr.fedorainfracloud.org-session.lock
[17:27:30] {/usr/lib/python3.10/site-packages/filelock/_api.py:157} DEBUG - Lock 140276775771568 acquired on /home/praiskup/.cache/copr/copr.fedorainfracloud.org-session.lock
[17:27:30] {/usr/lib/python3.10/site-packages/filelock/_api.py:187} DEBUG - Attempting to release lock 140276775771568 on /home/praiskup/.cache/copr/copr.fedorainfracloud.org-session.lock
[17:27:30] {/usr/lib/python3.10/site-packages/filelock/_api.py:190} DEBUG - Lock 140276775771568 released on /home/praiskup/.cache/copr/copr.fedorainfracloud.org-session.lock
[17:27:30] {/usr/lib/python3.10/site-packages/urllib3/connectionpool.py:1001} DEBUG - Starting new HTTPS connection (1): copr.fedorainfracloud.org:443
[17:27:32] {/usr/lib/python3.10/site-packages/urllib3/connectionpool.py:456} DEBUG - https://copr.fedorainfracloud.org:443 "GET /api_3/auth-check HTTP/1.1" 401 135
[17:27:32] {/usr/lib/python3.10/site-packages/filelock/_api.py:153} DEBUG - Attempting to acquire lock 140276775771568 on /home/praiskup/.cache/copr/copr.fedorainfracloud.org-session.lock
[17:27:32] {/usr/lib/python3.10/site-packages/filelock/_api.py:157} DEBUG - Lock 140276775771568 acquired on /home/praiskup/.cache/copr/copr.fedorainfracloud.org-session.lock
[17:27:32] {/usr/lib/python3.10/site-packages/filelock/_api.py:187} DEBUG - Attempting to release lock 140276775771568 on /home/praiskup/.cache/copr/copr.fedorainfracloud.org-session.lock
[17:27:32] {/usr/lib/python3.10/site-packages/filelock/_api.py:190} DEBUG - Lock 140276775771568 released on /home/praiskup/.cache/copr/copr.fedorainfracloud.org-session.lock
[17:27:32] {/usr/lib/python3.10/site-packages/urllib3/connectionpool.py:1001} DEBUG - Starting new HTTPS connection (1): copr.fedorainfracloud.org:443
[17:27:34] {/usr/lib/python3.10/site-packages/urllib3/connectionpool.py:456} DEBUG - https://copr.fedorainfracloud.org:443 "GET /api_3/auth-check HTTP/1.1" 200 28
Uploading package /home/praiskup/rh/packages/vim-fugitive-gitlab/vim-fugitive-gitlab-0~20220701gitb73a8e-1.fc36.src.rpm
[17:27:34] {/usr/lib/python3.10/site-packages/filelock/_api.py:153} DEBUG - Attempting to acquire lock 140276773853152 on /home/praiskup/.cache/copr/copr.fedorainfracloud.org-session.lock
[17:27:34] {/usr/lib/python3.10/site-packages/filelock/_api.py:157} DEBUG - Lock 140276773853152 acquired on /home/praiskup/.cache/copr/copr.fedorainfracloud.org-session.lock
[17:27:34] {/usr/lib/python3.10/site-packages/filelock/_api.py:187} DEBUG - Attempting to release lock 140276773853152 on /home/praiskup/.cache/copr/copr.fedorainfracloud.org-session.lock
[17:27:34] {/usr/lib/python3.10/site-packages/filelock/_api.py:190} DEBUG - Lock 140276773853152 released on /home/praiskup/.cache/copr/copr.fedorainfracloud.org-session.lock
[17:27:34] {/usr/lib/python3.10/site-packages/urllib3/connectionpool.py:1001} DEBUG - Starting new HTTPS connection (1): copr.fedorainfracloud.org:443
 |################################| 21.6 kB 76.2 kB/s eta 0:00:00[17:27:39] {/usr/lib/python3.10/site-packages/urllib3/connectionpool.py:456} DEBUG - https://copr.fedorainfracloud.org:443 "POST /api_3/build/create/upload HTTP/1.1" 401 135
[17:27:39] {/usr/lib/python3.10/site-packages/filelock/_api.py:153} DEBUG - Attempting to acquire lock 140276773849840 on /home/praiskup/.cache/copr/copr.fedorainfracloud.org-session.lock
[17:27:39] {/usr/lib/python3.10/site-packages/filelock/_api.py:157} DEBUG - Lock 140276773849840 acquired on /home/praiskup/.cache/copr/copr.fedorainfracloud.org-session.lock
[17:27:39] {/usr/lib/python3.10/site-packages/filelock/_api.py:187} DEBUG - Attempting to release lock 140276773849840 on /home/praiskup/.cache/copr/copr.fedorainfracloud.org-session.lock
[17:27:39] {/usr/lib/python3.10/site-packages/filelock/_api.py:190} DEBUG - Lock 140276773849840 released on /home/praiskup/.cache/copr/copr.fedorainfracloud.org-session.lock
[17:27:39] {/usr/lib/python3.10/site-packages/urllib3/connectionpool.py:1001} DEBUG - Starting new HTTPS connection (1): copr.fedorainfracloud.org:443
 |################################| 21.6 kB 3.8 kB/s eta 0:00:00 [17:27:59] {/usr/lib/python3.10/site-packages/urllib3/connectionpool.py:456} DEBUG - https://copr.fedorainfracloud.org:443 "POST /api_3/build/create/upload HTTP/1.1" 408 221


Something went wrong:
Error: Response is not in JSON format, there is probably a bug in the API code.

Server response:
----------------


408 Request Timeout

Request Timeout
Server timeout waiting for the HTTP request from the client.

While the server side logs show

2022-09-05 15:28:35,237 [INFO][/usr/share/copr/coprs_frontend/coprs/views/misc.py:194|misc:decorated_function][ANON] Attempting to use invalid or expired API login 'None'

Hmm, there actually is:

ep 05 15:40:10.195114 2022] [wsgi:error] [pid 2861153:tid 2861202] [client 213.175.37.12:6015] mod_wsgi (pid=2861153): Request data read error when proxying data to daemon process: The timeout specified has expired.
[Mon Sep 05 15:40:10.199003 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015] ERROR:coprs:Admin-only exception
[Mon Sep 05 15:40:10.199054 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015] Request: POST https://copr.fedorainfracloud.org/api_3/build/create/upload
[Mon Sep 05 15:40:10.199062 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015] User: praiskup
[Mon Sep 05 15:40:10.199068 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015] Traceback (most recent call last):
[Mon Sep 05 15:40:10.199073 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]   File "/usr/lib/python3.10/site-packages/werkzeug/wsgi.py", line 921, in read
[Mon Sep 05 15:40:10.199079 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]     read = self._read(to_read)
[Mon Sep 05 15:40:10.199091 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015] OSError: Apache/mod_wsgi request data read error: Partial results are valid but processing is incomplete.
[Mon Sep 05 15:40:10.199097 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015] 
[Mon Sep 05 15:40:10.199117 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015] During handling of the above exception, another exception occurred:
[Mon Sep 05 15:40:10.199123 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015] 
[Mon Sep 05 15:40:10.199128 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015] Traceback (most recent call last):
[Mon Sep 05 15:40:10.199133 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]   File "/usr/lib/python3.10/site-packages/werkzeug/formparser.py", line 142, in wrapper
[Mon Sep 05 15:40:10.199140 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]     return f(self, stream, *args, **kwargs)
[Mon Sep 05 15:40:10.199147 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]   File "/usr/lib/python3.10/site-packages/werkzeug/formparser.py", line 292, in _parse_multipart
[Mon Sep 05 15:40:10.199153 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]     form, files = parser.parse(stream, boundary, content_length)
[Mon Sep 05 15:40:10.199158 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]   File "/usr/lib/python3.10/site-packages/werkzeug/formparser.py", line 458, in parse
[Mon Sep 05 15:40:10.199166 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]     for data in iterator:
[Mon Sep 05 15:40:10.199178 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]   File "/usr/lib/python3.10/site-packages/werkzeug/wsgi.py", line 653, in _make_chunk_iter
[Mon Sep 05 15:40:10.199183 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]     item = _read(buffer_size)
[Mon Sep 05 15:40:10.199188 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]   File "/usr/lib/python3.10/site-packages/werkzeug/wsgi.py", line 923, in read
[Mon Sep 05 15:40:10.199193 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]     return self.on_disconnect()
[Mon Sep 05 15:40:10.199197 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]   File "/usr/lib/python3.10/site-packages/werkzeug/wsgi.py", line 893, in on_disconnect
[Mon Sep 05 15:40:10.199202 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]     raise ClientDisconnected()
[Mon Sep 05 15:40:10.199225 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015] werkzeug.exceptions.ClientDisconnected: 400 Bad Request: The browser (or proxy) sent a request that this server could not understand.
[Mon Sep 05 15:40:10.199230 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015] 
[Mon Sep 05 15:40:10.199234 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015] During handling of the above exception, another exception occurred:
[Mon Sep 05 15:40:10.199239 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015] 
[Mon Sep 05 15:40:10.199243 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015] Traceback (most recent call last):
[Mon Sep 05 15:40:10.199247 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]   File "/usr/lib/python3.10/site-packages/flask/app.py", line 1513, in full_dispatch_request
[Mon Sep 05 15:40:10.199252 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]     rv = self.dispatch_request()
[Mon Sep 05 15:40:10.199257 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]   File "/usr/lib/python3.10/site-packages/flask/app.py", line 1499, in dispatch_request
[Mon Sep 05 15:40:10.199261 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]     return self.ensure_sync(self.view_functions[rule.endpoint])(**req.view_args)
[Mon Sep 05 15:40:10.199267 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]   File "/usr/share/copr/coprs_frontend/coprs/views/misc.py", line 203, in decorated_function
[Mon Sep 05 15:40:10.199286 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]     return f(*args, **kwargs)
[Mon Sep 05 15:40:10.199292 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]   File "/usr/share/copr/coprs_frontend/coprs/views/apiv3_ns/__init__.py", line 80, in file_upload_wrapper
[Mon Sep 05 15:40:10.199296 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]     if "json" in flask.request.files:
[Mon Sep 05 15:40:10.199301 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]   File "/usr/lib/python3.10/site-packages/werkzeug/utils.py", line 97, in __get__
[Mon Sep 05 15:40:10.199306 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]     value = self.fget(obj)  # type: ignore
[Mon Sep 05 15:40:10.199310 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]   File "/usr/lib/python3.10/site-packages/werkzeug/wrappers/request.py", line 499, in files
[Mon Sep 05 15:40:10.199315 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]     self._load_form_data()
[Mon Sep 05 15:40:10.199319 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]   File "/usr/lib/python3.10/site-packages/flask/wrappers.py", line 113, in _load_form_data
[Mon Sep 05 15:40:10.199324 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]     RequestBase._load_form_data(self)
[Mon Sep 05 15:40:10.199328 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]   File "/usr/lib/python3.10/site-packages/werkzeug/wrappers/request.py", line 285, in _load_form_data
[Mon Sep 05 15:40:10.199333 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]     data = parser.parse(
[Mon Sep 05 15:40:10.199338 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]   File "/usr/lib/python3.10/site-packages/werkzeug/formparser.py", line 265, in parse
[Mon Sep 05 15:40:10.199345 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]     return parse_func(self, stream, mimetype, content_length, options)
[Mon Sep 05 15:40:10.199351 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]   File "/usr/lib/python3.10/site-packages/werkzeug/formparser.py", line 150, in wrapper
[Mon Sep 05 15:40:10.199356 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015]     chunk = stream.read(1024 * 64)
[Mon Sep 05 15:40:10.199361 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015] OSError: Apache/mod_wsgi request data read error: Input is already in error state.
[Mon Sep 05 15:40:10.199701 2022] [wsgi:error] [pid 2860748:tid 2861084] [remote 213.175.37.12:6015] ERROR:coprs:Response error: 500 Request wasn't successful, there is probably a bug in the Copr code.

Log in to comment on this ticket.

Metadata
Related Pull Requests
  • #2304 Merged 2 years ago