Pac4cli recently broke on Ubuntu 20.04

[johnsonb88]

Pac4cli (Ubuntu 20.04 PPA version) had been working great for years, but broke within the last few days:

> pac4cli --loglevel=debug
INFO [9718]: pac4cli: Starting proxy server on 127.0.0.1:None
ERROR [9718]: pac4cli: Problem starting the server
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/pac4cli/__main__.py", line 105, in main
    yield start_server(args.bind, args.port, reactor)
TypeError: an integer is required (got type NoneType)

> python3 -m twisted --version
18.9.0

I assume this is due to a change in the version of one of its dependencies, possibly twisted.
Any suggestions? I'm happy to gather more info.

[tkluck]

Hi @johnsonb88 , thanks for the bug report. The pac4cli command line has required the -p or --port option for a long time and it's missing in your example input/output. Would you be able to run

pac4cli --loglevel=debug --port=23128

and paste the output here? Another command that I'd be interested in is

journalctl -u pac4cli.service

Thank you!

[johnsonb88]

@tkluck, thanks for the help. If I start pac4cli manually with "--port", it seems to work:

> pac4cli --loglevel=debug --port=23128
INFO [318838]: pac4cli: Starting proxy server on 127.0.0.1:23128
INFO [318838]: pac4cli: Successfully started; getting first configuration.
INFO [318838]: pac4cli: Updating WPAD configuration...
DEBUG [318838]: pac4cli: No configuration file specified
INFO [318838]: pac4cli: Trying to get wpad url from NetworkManager DHCP...
DEBUG [318838]: pac4cli: Inspecting connection /org/freedesktop/NetworkManager/ActiveConnection/1
DEBUG [318838]: pac4cli: Its Dhcp4 configuration is /org/freedesktop/NetworkManager/DHCP4Config/1
DEBUG [318838]: pac4cli: Its options are {'dhcp_lease_time': '7200', 'domain_name_servers': '192.168.29.1 192.168.29.1', 'expiry': '1653322531', 'host_name': 'bjj-laptop2', 'ip_address': '192.168.29.175', 'next_server': '192.168.29.1', 'requested_broadcast_address': '1', 'requested_domain_name': '1', 'requested_domain_name_servers': '1', 'requested_domain_search': '1', 'requested_host_name': '1', 'requested_interface_mtu': '1', 'requested_ms_classless_static_routes': '1', 'requested_nis_domain': '1', 'requested_nis_servers': '1', 'requested_ntp_servers': '1', 'requested_rfc3442_classless_static_routes': '1', 'requested_root_path': '1', 'requested_routers': '1', 'requested_static_routes': '1', 'requested_subnet_mask': '1', 'requested_time_offset': '1', 'requested_wpad': '1', 'routers': '192.168.29.1', 'subnet_mask': '255.255.255.0'}
INFO [318838]: pac4cli: Trying to get wpad url from NetworkManager domains...
DEBUG [318838]: pac4cli: Inspecting connection /org/freedesktop/NetworkManager/ActiveConnection/1
DEBUG [318838]: pac4cli: Its IP4 configuration is /org/freedesktop/NetworkManager/IP4Config/4
DEBUG [318838]: pac4cli: Its domains are []
INFO [318838]: pac4cli: None of the tried urls seem to have worked; falling back to direct
INFO [318838]: pac4cli: Have first configuration.

(That looks correct: there's no proxy on my current network.)
So I guess it's not the core of pac4cli. But the service is still having trouble, in a restart loop:

> sudo systemctl start pac4cli.service
Job for pac4cli.service failed because a timeout was exceeded.
See "systemctl status pac4cli.service" and "journalctl -xe" for details.

> systemctl status pac4cli.service
● pac4cli.service - PAC autoconfigured proxy for use through http_proxy= environment variables
     Loaded: loaded (/lib/systemd/system/pac4cli.service; disabled; vendor preset: enabled)
     Active: activating (start) since Mon 2022-05-23 09:46:55 CDT; 13s ago
   Main PID: 319005 (pac4cli)
      Tasks: 2 (limit: 18961)
     Memory: 27.0M
     CGroup: /system.slice/pac4cli.service
             ├─319005 /bin/sh /usr/bin/pac4cli -p 3128 --systemd --config /etc/pac4cli/pac4cli.config >
             └─319006 /usr/bin/python3 -m pac4cli -p 3128 --systemd --config /etc/pac4cli/pac4cli.conf>

> journalctl --no-pager -u pac4cli.service
-- Logs begin at Mon 2022-05-23 09:54:05 CDT, end at Mon 2022-05-23 10:01:21 CDT. --
May 23 09:54:28 bjj-laptop2 systemd[1]: pac4cli.service: start operation timed out. Terminating.
May 23 09:54:28 bjj-laptop2 systemd[1]: pac4cli.service: Failed with result 'timeout'.
May 23 09:54:28 bjj-laptop2 systemd[1]: Failed to start PAC autoconfigured proxy for use through http_proxy= environment variables.
May 23 09:54:28 bjj-laptop2 systemd[1]: pac4cli.service: Scheduled restart job, restart counter is at 6.
May 23 09:54:28 bjj-laptop2 systemd[1]: Stopped PAC autoconfigured proxy for use through http_proxy= environment variables.
May 23 09:54:28 bjj-laptop2 systemd[1]: Starting PAC autoconfigured proxy for use through http_proxy= environment variables...
May 23 09:55:58 bjj-laptop2 systemd[1]: pac4cli.service: start operation timed out. Terminating.
May 23 09:55:58 bjj-laptop2 systemd[1]: pac4cli.service: Failed with result 'timeout'.
May 23 09:55:58 bjj-laptop2 systemd[1]: Failed to start PAC autoconfigured proxy for use through http_proxy= environment variables.
  ...

[tkluck]

@johnsonb88 , could it be that you installed another proxy on your system that's listening on port 3128? It's the default port for proxies.

The command ss -tlp should be able to tell you. If this is the issue, we have #3 open for it.

[johnsonb88]

could it be that you installed another proxy on your system that's listening on port 3128?

No, I don't think that's it, at least there's not one that's running at the moment:

> ss -tlnp | grep 3128 |wc -c
0

Thanks for the debugging help.

[tkluck]

No, I don't think that's it, at least there's not one that's running at the moment:

I see. There's not a lot to go on from the logs, so I was just trying to think of differences between your manual run and the systemd run. The port (23128 vs 3128) was an obvious thing to try.

I'll see if I can reproduce and post here if I have any updates.

[tkluck]

Hey @johnsonb88 , I have reason to believe this may be related to systemd/systemd#22737. Would you be able to confirm this for me? Here's how to do that.

Run

sudo systemctl edit pac4cli.service

which will open up an editor for an override file. Add the following override:

[Service]
DynamicUser=false

Then,

sudo systemctl daemon-reload # not sure if needed
sudo systemctl restart pac4cli.service

Let me know how it goes!

[johnsonb88]

I have reason to believe this may be related to systemd/systemd#22737. Would you be able to confirm this for me?

Running the steps you suggested to set DynamicUser=false seems to fix it. Pac4cli started up normally, and I verified using curl that it was able to handle requests.

Thanks! Do you plan to publish a change to the service file, or wait and let this get sorted out upstream in systemd? It looks like several projects were affected.

[tkluck]

Thanks for confirming.

Do you plan to publish a change to the service file, or wait and let this get sorted out upstream in systemd?

I'll wait for upstream to sort this out, because I don't think I'll be able to do anything quicker than them. Also, the dynamicuser provides security. I'll leave this bug open so it's easy to find for others who run into the same.