Issue 2551417
Created on 2026-05-18 07:22 by rboylan, last changed 2026-05-19 05:35 by rouilj.
| Messages | |||
|---|---|---|---|
| msg8436 | Author: [hidden] (rboylan) | Date: 2026-05-18 07:22 | |
After hg cloning the source and starting the demo, I pointed my Firefox 140.19.2esr browser at the localhost port the demo said to use. I logged in with demo/demo and got no response. On the terminal from which the demo launched:
127.0.0.1 - - [18/May/2026 06:15:21] "GET /demo/ HTTP/1.1" 200 -
127.0.0.1 - - [18/May/2026 06:15:21] "GET /demo/@@file/style.css HTTP/1.1" 200 -
127.0.0.1 - - [18/May/2026 06:15:21] "GET /demo/@@file/classhelper.js HTTP/1.1" 200 -
127.0.0.1 - - [18/May/2026 06:15:21] "GET /demo/@@file/datecopy.min.js HTTP/1.1" 200 -
127.0.0.1 - - [18/May/2026 06:15:22] "GET /demo/rest HTTP/1.1" 403 -
127.0.0.1 - - [18/May/2026 06:15:22] "GET /favicon.ico HTTP/1.1" 200 -
127.0.0.1 - - [18/May/2026 06:15:49] "POST /demo/ HTTP/1.1" 302 -
127.0.0.1 - - [18/May/2026 06:15:49] "GET /demo/?%40ok_message=Welcome+demo%21 HTTP/1.1" 200 -
127.0.0.1 - - [18/May/2026 06:15:49] "GET /demo/rest HTTP/1.1" 200 -
127.0.0.1 - - [18/May/2026 06:15:49] "GET /favicon.ico HTTP/1.1" 200 -
127.0.0.1 - - [18/May/2026 06:15:49] "GET /favicon.ico HTTP/1.1" 400 -
EXCEPTION AT Mon May 18 06:15:49 2026
Traceback (most recent call last):
File "/usr/local/src/roundup/roundup/scripts/roundup_server.py", line 275, in run_cgi
self.inner_run_cgi()
File "/usr/local/src/roundup/roundup/scripts/roundup_server.py", line 418, in inner_run_cgi
self.wfile.write(data)
File "/usr/lib/python3.9/socketserver.py", line 799, in write
self._sock.sendall(b)
BrokenPipeError: [Errno 32] Broken pipe
There were 2 more broken pipe errors as the attempt to handle the initial exception led to more exceptions (with the same broken pipe error).
Since the server has not returned to the command prompt I guess it's still running and this is not technically a crash. But it doesn't work. Not a good look for a first encounter with the system.
Environment
===========
Python 3.9
Debian GNU/Linux 11
I do have a firewall running, but I don't think it covers the loopback interface. There are various other security systems active, including AppArmor and some process isolation, I think. Running under SystemD.
Linux barley 5.10.0-42-amd64 #1 SMP Debian 5.10.251-4 (2026-05-08) x86_64 GNU/Linux
I was running as myself, not root.
|
|||
| msg8438 | Author: [hidden] (rouilj) | Date: 2026-05-18 16:57 | |
Hi Ross: I'm sorry you are running into issues with Roundup. I tried to duplicate your steps but I am using linux mint 22.3, python 3.12, and firefox 146.0.1. Note that 3.9 Python support maybe dropped in Roundup 2.6 due for release in July. You are running 2.6 by using the repository version rather than a released pip installed version of Roundup. However, what you are seeing is not expected. > 127.0.0.1 - - [18/May/2026 06:15:49] "POST /demo/ HTTP/1.1" 302 - > 127.0.0.1 - - [18/May/2026 06:15:49] "GET /demo/?%40ok_message=Welcome+demo%21 HTTP/1.1" 200 - > 127.0.0.1 - - [18/May/2026 06:15:49] "GET /demo/rest HTTP/1.1" 200 - > 127.0.0.1 - - [18/May/2026 06:15:49] "GET /favicon.ico HTTP/1.1" 200 - > 127.0.0.1 - - [18/May/2026 06:15:49] "GET /favicon.ico HTTP/1.1" 400 - > EXCEPTION AT Mon May 18 06:15:49 2026 This is odd, you shouldn't have two favicon requests. Also they shouldn't have two different statuses: 200 and 400. When I duplicated your steps, the logging looked the same up to the GET /demo/rest. After that I do not have the favicon.ico requests. (favicon.ico should have been cached when the browser loaded the login screen.) I have a GET for "/demo/?%40template=translation&properties ....." which is the classhelper.js module getting translated strings for its interface. Do you have javascript enabled on your browser? While I do not get an exception, I get three timeouts after a minute which is expected. My claim is something is closing the browser/roundup connection. I am not sure what. Are you experienced in using the firefox devtools, maybe something on the network tab may shed some light on this. On the bright side, I think you may have given me a solution to another issue. It looks like the BrokenPipeError should be trapped and discarded like a ConnectionAbortedError. Roundup runs in many different environments: stand alone server (which is used by demo.py) behind a proxy (e.g. pound, apache, nginx ... in reverse proxy mode) as a wsgi process using a wsgi server (gunicorn, Waitress) as a Zope framework module and all of these handle and expose network and other errors a little differently. Even though Roundup should not be seeing a BrokenPipeError, it should be handled better. I'll see if I can make some changes to handle it better. -- rouilj |
|||
| msg8440 | Author: [hidden] (rouilj) | Date: 2026-05-18 18:59 | |
Hi Ross:
I'm unable to generate a BrokenPipeError using the tools I have.
However, I do now understand the reason a BrokenPipeError generated
two more exceptions. The last resort Exception handler tries to report
the problem to the client. When the client is gone, it produces more
exceptions when writing to the closed socket.
I added the following near line 284 in roundup/scripts/roundup_server.py:
except (BrokenPipeError, ConnectionAbortedError, ConnectionResetError) as e:
self.log_info("Client has gone: %s", e)
right before:
except Exception:
whose block includes the words "EXCEPTION AT".
Can you patch the code and verify that you do not get a traceback on a BrokenPipeError
and instead get a log message.
Thanks.
-- rouilj
|
|||
| msg8441 | Author: [hidden] (rboylan) | Date: 2026-05-18 23:31 | |
There's an error in the new code: self has no log_info attribute. Also, I had to add a ) at the end of demo.py before it would run. As detailed in my comments below, I found some of the messages from the demo (perhaps actually from the server?) confusing. Steps ===== Updated to the latest, 8649 : cafa177776bb. By the way I looked for the new documentation when your reported it changed for my other bug, but didn't see it. It (r8648) did show up a couple of hours later. Then I applied the change you suggested before line 284 in roundup/scripts/roundup_server.py. Here's the transcript, with added # commentary. # On the terminal where I launched the demo yesterday # Still hadn't returned to prompt, and so probably running. ^CKeyboard Interrupt: exiting ross@barley:/usr/local/src/roundup$ date; python3 ./demo.py -b sqlite Mon 18 May 2026 03:25:25 PM PDT Traceback (most recent call last): File "/usr/local/src/roundup/./demo.py", line 5, in <module> from roundup.demo import main File "/usr/local/src/roundup/roundup/demo.py", line 137 sys.exit(2) ^ SyntaxError: invalid syntax # Edited demo.py to fix the apparent missing ) at the end of the previous line ross@barley:/usr/local/src/roundup$ date; python3 ./demo.py -b sqlite Mon 18 May 2026 03:28:30 PM PDT Error: Arguments are not allowed when running an existing demo. Use the 'nuke' command to start over. # Since I don't think I am running the demo, since I ^C'd it, # this error surprised me. It also made me wonder if it was still # running, in which case it would have loaded the code before # the recent edits. Or it could just mean some lock or configuration # files were still around. ross@barley:/usr/local/src/roundup$ date; python3 ./demo.py nuke Mon 18 May 2026 03:28:53 PM PDT Initializing demo instance in: /usr/local/src/roundup/demo Nuking directory left from the previous demo instance. Trying to set up web server on port 8917 ... # same port, which argues against the previous instance being active should be ok. # ... [boilerplate deleted] # but it says to change backend types I must use nuke. # but I just used nuke... ^CKeyboard Interrupt: exiting ross@barley:/usr/local/src/roundup$ date; python3 ./demo.py nuke Mon 18 May 2026 03:29:34 PM PDT Initializing demo instance in: /usr/local/src/roundup/demo Nuking directory left from the previous demo instance. Trying to set up web server on port 8917 ... should be ok. Demo Tracker Home: /usr/local/src/roundup/demo Server running - connect to: http://localhost:8917/demo/ # ... deletions # At this point I pointed Firefox at the port 127.0.0.1 - - [18/May/2026 15:31:10] "GET / HTTP/1.1" 302 - 127.0.0.1 - - [18/May/2026 22:31:11] "GET /demo/index HTTP/1.1" 200 - 127.0.0.1 - - [18/May/2026 22:31:11] "GET /demo/@@file/style.css HTTP/1.1" 200 - 127.0.0.1 - - [18/May/2026 22:31:11] "GET /demo/@@file/classhelper.js HTTP/1.1" 200 - 127.0.0.1 - - [18/May/2026 22:31:11] "GET /demo/@@file/datecopy.min.js HTTP/1.1" 200 - 127.0.0.1 - - [18/May/2026 22:31:11] "GET /demo/rest HTTP/1.1" 403 - 127.0.0.1 - - [18/May/2026 22:31:12] "GET /favicon.ico HTTP/1.1" 200 - # and here it stopped for awhile # I don't think I touched any of the controls on the window, and certainly # did not try to login 127.0.0.1 - - [18/May/2026 22:32:12] Request timed out: timeout('timed out') # after seeing the previous message, I did try to login as demo 127.0.0.1 - - [18/May/2026 22:32:23] "POST /demo/ HTTP/1.1" 302 - 127.0.0.1 - - [18/May/2026 22:32:23] "GET /demo/index?%40ok_message=Welcome+demo%21 HTTP/1.1" 200 - 127.0.0.1 - - [18/May/2026 22:32:23] "GET /demo/rest HTTP/1.1" 200 - 127.0.0.1 - - [18/May/2026 22:32:23] "GET /favicon.ico HTTP/1.1" 200 - ---------------------------------------- Exception occurred during processing of request from ('127.0.0.1', 43348) Traceback (most recent call last): File "/usr/local/src/roundup/roundup/scripts/roundup_server.py", line 275, in run_cgi self.inner_run_cgi() File "/usr/local/src/roundup/roundup/scripts/roundup_server.py", line 420, in inner_run_cgi self.wfile.write(data) File "/usr/lib/python3.9/socketserver.py", line 799, in write self._sock.sendall(b) BrokenPipeError: [Errno 32] Broken pipe # Since there is no "Client has gone" message, it seems the new # except clause didn't activate. However it's the next reported # error, and so this may just reflect the order in which nested errors # are reported. # Line 275 is reported as the most # recent call, and it certainly looks as if it's covered by the new except # The next failure definitely reflects the new code. # Unfortunately, the new code has an error. During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/lib/python3.9/socketserver.py", line 616, in process_request self.finish_request(request, client_address) File "/usr/lib/python3.9/socketserver.py", line 360, in finish_request self.RequestHandlerClass(request, client_address, self) File "/usr/lib/python3.9/socketserver.py", line 720, in __init__ self.handle() File "/usr/local/src/roundup/roundup/scripts/roundup_server.py", line 333, in handle_method_wrapper http_.server.BaseHTTPRequestHandler.handle(self) File "/usr/lib/python3.9/http/server.py", line 436, in handle self.handle_one_request() File "/usr/lib/python3.9/http/server.py", line 422, in handle_one_request method() File "/usr/local/src/roundup/roundup/scripts/roundup_server.py", line 285, in run_cgi self.log_info("Client has gone: %s", e) AttributeError: 'RequestHandler' object has no attribute 'log_info' ---------------------------------------- 127.0.0.1 - - [18/May/2026 22:32:23] "GET /demo/?%40template=translation&properties=apply%2Ccancel%2Cnext%2Cprev%2Csearch%2Creset%2CInfo+on+%7BclassName%7D+-+%7BitemDesignator%7D+-+Classhelper HTTP/1.1" 200 - 127.0.0.1 - - [18/May/2026 22:33:23] Request timed out: timeout('timed out') # timeouts seem to be after 60s |
|||
| msg8442 | Author: [hidden] (rboylan) | Date: 2026-05-18 23:47 | |
javascript is enabled in my browser. After my seemingly abortive login I activate devtools in FF and hit the logout button on the demo screen. The devtools log under network shows a series of successful GET and then one with Status 403 (denied). The file column says "rest" and the initiator is classhelper.js:1371. There is one successful GET after for favicon.ico, which is reported as cached. |
|||
| msg8444 | Author: [hidden] (rouilj) | Date: 2026-05-19 05:35 | |
Hi Ross: I'm including another dev on this. I am rapidly running out of ideas as to the cause here. Ralf, if you have a chance can you look at this issue and see if you have any ideas? Covering a couple of replies here: > Also, I had to add a ) at the end of demo.py before it would run. You are correct I was missing a close ) on the prior line. That is fixed. I incorrectly transcribed the line from the live CD devel system to the system I use for checkin. I am using a live CD booted system so I can be sure I am running in a clean system. > There's an error in the new code: self has no log_info attribute. self.log_info() should be self.log_message() Regarding: > Error: Arguments are not allowed when running an existing demo. > Use the 'nuke' command to start over. just run 'python ./demo.py' with no arguments. It will discover the existing demo tracker and serve it. The directions from the script say: 1. Log in as "demo"/"demo" or "admin"/"admin". 2. Hit Control-C to stop the server. 3. Re-start the server by running "./demo.py" again. 4. Reset the tracker by running "./demo.py nuke". Would it be better if 3 reads: 3. Re-start the server by running "./demo.py" without any arguments. demo.py always uses ./demo as the tracker home directory. If run without arguments it prompts you for database etc. interactively. All the arguments are for use when recreating a tracker. It looks like the traceback in msg8441 has the sequence I expect. > 127.0.0.1 - - [18/May/2026 15:31:10] "GET / HTTP/1.1" 302 - > 127.0.0.1 - - [18/May/2026 22:31:11] "GET /demo/index HTTP/1.1" 200 - > 127.0.0.1 - - [18/May/2026 22:31:11] "GET /demo/@@file/style.css HTTP/1.1" 200 - > [... 2 lines] > 127.0.0.1 - - [18/May/2026 22:31:11] "GET /demo/rest HTTP/1.1" 403 - The 403 is expected as you have not logged in yet. So you are the anonymous user. The anonymous user doesn't have permissions to use the rest interface and gets a 403. > 127.0.0.1 - - [18/May/2026 22:31:12] "GET /favicon.ico HTTP/1.1" 200 - > # and here it stopped for awhile Yup the request is done. Nothing more to do until you touch the browser. > # I don't think I touched any of the controls on the window, and certainly > # did not try to login > 127.0.0.1 - - [18/May/2026 22:32:12] Request timed out: timeout('timed out') Timeout about 1 minute after the last message as expected. > # after seeing the previous message, I did try to login as demo > 127.0.0.1 - - [18/May/2026 22:32:23] "POST /demo/ HTTP/1.1" 302 - > 127.0.0.1 - - [18/May/2026 22:32:23] "GET /demo/index?%40ok_message=Welcome [...] > 127.0.0.1 - - [18/May/2026 22:32:23] "GET /demo/rest HTTP/1.1" 200 - This GET succeeds since you have logged in as demo. The demo user has the role 'user' which does have permission to access the rest interface. > 127.0.0.1 - - [18/May/2026 22:32:23] "GET /favicon.ico HTTP/1.1" 200 - ---------------------------------------- Exception occurred during processing of request from ('127.0.0.1', 43348) Traceback (most recent call last): File "/usr/local/src/roundup/roundup/scripts/roundup_server.py", line 275, in run_cgi self.inner_run_cgi() File "/usr/local/src/roundup/roundup/scripts/roundup_server.py", line 420, in inner_run_cgi self.wfile.write(data) File "/usr/lib/python3.9/socketserver.py", line 799, in write self._sock.sendall(b) BrokenPipeError: [Errno 32] Broken pipe # Since there is no "Client has gone" message, it seems the new # except clause didn't activate. However it's the next reported # error, and so this may just reflect the order in which nested errors # are reported. I think you are right. Since the exception code threw an exception 8-/, it just dumped the exceptions in creation order. # Line 275 is reported as the most # recent call, and it certainly looks as if it's covered by the new except # The next failure definitely reflects the new code. # Unfortunately, the new code has an error. Replace log_info with log_message() as above and see if that generates the Client has gone message. As to why you are getting the BrokenPipeError, I still have no idea. That code is doing the following: buffer the status response, buffer some headers, end headers which writes the buffered headers and IIRC a blank line using self.wfile.write. So at this point the client connection is open. then we try to write the data and get the BrokenPipeError indicating the client connection is closed. My WAG is that something in the headers is causing the issue. My WAG was that this call: self.send_header('Content-Length', len(favico)) is sending 0 as the len of favico. That could cause the browser to close the connection since there is nothing to read. However we already got the favico in the original get and it should be cached. I also just tried replacing len(favico) with 0 (and 20) and I don't get a BrokenPipeError in my environment. This is with Roundup running in HTTP/1.1 or HTTP/1.0 modes. Can you use the devtools to look at the login sequence and see what the favicon request looks like. The headers tab for the favico request should show a Content-Length of 1406 and the response tab should show the cowboy on a horse. You orginally reported: > I logged in with demo/demo and got no response. This is really weird as you indicated that you are actually logged in. The favicon failing shouldn't change anything as it is a totally separate request. You got the login page back according to the logs. Do you have any Firefox plugins that act as sanitizers or block bad pages? One other thing to try is to rather than running demo.py run: python roundup/scripts/roundup_server -p 8917 -V HTTP/1.0 demo=demo roundup_server is what demo.py is running under the hood. This should cause roundup_server to use HTTP version 1.0 rather than the default of version 1.1. So every connection is closed after the response. This should eliminate the timeout log as well. Do you have another graphical browser available? You can use a text mode browser like w3m or lynx, but they won't get the favicon which is where things fail. I doubt curl for favico would trigger the issue. Trying a different version of firefox or chrome might be helpful. You can change demo/config.ini's 'web' stting from localhost:8917 to hostname:8917 and try connecting from another computer if you have one. Thanks for bringing me an interesting problem. -- rouilj |
|||
| History | |||
|---|---|---|---|
| Date | User | Action | Args |
| 2026-05-19 05:35:42 | rouilj | set | status: new -> open nosy: + schlatterbeck messages: + msg8444 |
| 2026-05-18 23:47:35 | rboylan | set | messages: + msg8442 |
| 2026-05-18 23:31:18 | rboylan | set | status: open -> new messages: + msg8441 |
| 2026-05-18 18:59:17 | rouilj | set | status: new -> open |
| 2026-05-18 18:59:08 | rouilj | set | messages: + msg8440 |
| 2026-05-18 16:57:59 | rouilj | set | assignee: rouilj messages: + msg8438 nosy: + rouilj |
| 2026-05-18 07:22:35 | rboylan | create | |