The maximum number of active connections for UID 0 has been reached
denilsonsa opened this issue · 4 comments
denilsonsa commented
I don't know the exact steps on how to reproduce it. It happened once to me, and caused major issues that force me to restart my laptop.
I'm running Ubuntu 18.04, with LXDE (Lubuntu) as the desktop, on a laptop machine. pac4cli is installed through the PPA. The laptop had about 14 days of uptime when that happened. I also had a docker container running (for quite some time), which spawned a couple of virtual network interfaces (not sure if it is related or not).
I've found these entries on my /var/log/syslog (I've removed some noisy non-relevant lines):
Nov 27 16:12:55 /usr/lib/python3/dist-packages/pac4cli/__main__.py[4517]: WARNING [4517]: pac4cli: Problem getting wpad option for connection /org/freedesktop/NetworkManager/ActiveConnection/26#012Traceback (most recent call last):#012 File "/usr/lib/python3/dist-packages/pac4cli/wpad.py", line 84, in get_wpad_url#012 'org.freedesktop.NetworkManager.Connection.Active', 'Dhcp4Config')#012txdbus.error.RemoteError: org.freedesktop.DBus.Error.UnknownMethod: No such interface 'org.freedesktop.DBus.Properties' on object at path /org/freedesktop/NetworkManager/ActiveConnection/26
Nov 27 16:12:55 systemd-sleep[27931]: Suspending system...
Nov 27 16:20:28 dbus-daemon[1128]: [system] The maximum number of active connections for UID 0 has been reached (max_connections_per_user=256)
Nov 27 16:20:28 /usr/lib/python3/dist-packages/pac4cli/__main__.py[4517]: WARNING [4517]: pac4cli: Issue getting wpad configuration#012Traceback (most recent call last):#012 File "/usr/lib/python3/dist-packages/pac4cli/__main__.py", line 70, in get_possible_configuration_locations#012 urls = yield wpad.getUrls()#012txdbus.error.RemoteError: org.freedesktop.DBus.Error.LimitsExceeded: The maximum number of active connections for UID 0 has been reached
Nov 28 10:37:09 pac4cli[4513]: Unhandled Error
Nov 28 10:37:09 pac4cli[4513]: Traceback (most recent call last):
Nov 28 10:37:09 pac4cli[4513]: File "/usr/lib/python3.6/runpy.py", line 85, in _run_code
Nov 28 10:37:09 pac4cli[4513]: exec(code, run_globals)
Nov 28 10:37:09 pac4cli[4513]: File "/usr/lib/python3/dist-packages/pac4cli/__main__.py", line 145, in <module>
Nov 28 10:37:09 pac4cli[4513]: reactor.run()
Nov 28 10:37:09 pac4cli[4513]: File "/usr/lib/python3/dist-packages/twisted/internet/base.py", line 1243, in run
Nov 28 10:37:09 pac4cli[4513]: self.mainLoop()
Nov 28 10:37:09 pac4cli[4513]: File "/usr/lib/python3/dist-packages/twisted/internet/base.py", line 1252, in mainLoop
Nov 28 10:37:09 pac4cli[4513]: self.runUntilCurrent()
Nov 28 10:37:09 pac4cli[4513]: --- <exception caught here> ---
Nov 28 10:37:09 pac4cli[4513]: File "/usr/lib/python3/dist-packages/twisted/internet/base.py", line 851, in runUntilCurrent
Nov 28 10:37:09 pac4cli[4513]: f(*a, **kw)
Nov 28 10:37:09 pac4cli[4513]: File "/usr/lib/python3/dist-packages/twisted/internet/base.py", line 627, in stop
Nov 28 10:37:09 pac4cli[4513]: "Can't stop reactor that isn't running.")
Nov 28 10:37:09 pac4cli[4513]: twisted.internet.error.ReactorNotRunning: Can't stop reactor that isn't running.
Nov 28 10:37:09 pac4cli[4513]: Unhandled Error
Nov 28 10:37:09 pac4cli[4513]: Traceback (most recent call last):
Nov 28 10:37:09 pac4cli[4513]: File "/usr/lib/python3.6/runpy.py", line 85, in _run_code
Nov 28 10:37:09 pac4cli[4513]: exec(code, run_globals)
Nov 28 10:37:09 pac4cli[4513]: File "/usr/lib/python3/dist-packages/pac4cli/__main__.py", line 145, in <module>
Nov 28 10:37:09 pac4cli[4513]: reactor.run()
Nov 28 10:37:09 pac4cli[4513]: File "/usr/lib/python3/dist-packages/twisted/internet/base.py", line 1243, in run
Nov 28 10:37:09 pac4cli[4513]: self.mainLoop()
Nov 28 10:37:09 pac4cli[4513]: File "/usr/lib/python3/dist-packages/twisted/internet/base.py", line 1252, in mainLoop
Nov 28 10:37:09 pac4cli[4513]: self.runUntilCurrent()
Nov 28 10:37:09 pac4cli[4513]: --- <exception caught here> ---
Nov 28 10:37:09 pac4cli[4513]: File "/usr/lib/python3/dist-packages/twisted/internet/base.py", line 851, in runUntilCurrent
Nov 28 10:37:09 pac4cli[4513]: f(*a, **kw)
Nov 28 10:37:09 pac4cli[4513]: File "/usr/lib/python3/dist-packages/twisted/internet/base.py", line 627, in stop
Nov 28 10:37:09 pac4cli[4513]: "Can't stop reactor that isn't running.")
Nov 28 10:37:09 pac4cli[4513]: twisted.internet.error.ReactorNotRunning: Can't stop reactor that isn't running.
Nov 28 10:37:09 pac4cli[4513]: ['127.0.0.1']
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/:A-0000072/cgroup/eventpoll_pwq(1972:pac4cli.service)"
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/:A-0000128/cgroup/eventpoll_epi(1972:pac4cli.service)"
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/sock_inode_cache/cgroup/sock_inode_cache(1972:pac4cli.service)"
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/:A-0000208/cgroup/vm_area_struct(1972:pac4cli.service)"
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/:A-0002112/cgroup/mm_struct(1972:pac4cli.service)"
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/:A-0000704/cgroup/files_cache(1972:pac4cli.service)"
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/proc_inode_cache/cgroup/proc_inode_cache(1972:pac4cli.service)"
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/inode_cache/cgroup/inode_cache(1972:pac4cli.service)"
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/sighand_cache/cgroup/sighand_cache(1972:pac4cli.service)"
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/:A-0000256/cgroup/filp(1972:pac4cli.service)"
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/:A-0000192/cgroup/cred_jar(1972:pac4cli.service)"
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/:A-0005952/cgroup/task_struct(1972:pac4cli.service)"
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/:A-0001024/cgroup/signal_cache(1972:pac4cli.service)"
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/anon_vma/cgroup/anon_vma(1972:pac4cli.service)"
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/:A-0000064/cgroup/pid(1972:pac4cli.service)"
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/:0002048/cgroup/kmalloc-2048(1972:pac4cli.service)"
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/:0004096/cgroup/kmalloc-4096(1972:pac4cli.service)"
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/:0000256/cgroup/kmalloc-256(1972:pac4cli.service)"
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/:0000512/cgroup/kmalloc-512(1972:pac4cli.service)"
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/:0000096/cgroup/kmalloc-96(1972:pac4cli.service)"
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/:0000192/cgroup/kmalloc-192(1972:pac4cli.service)"
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/:0001024/cgroup/kmalloc-1024(1972:pac4cli.service)"
Nov 28 10:37:09 snapd[25277]: udevmon.go:184: udev monitor observed remove event for unknown device "/sys/kernel/slab/:0000064/cgroup/kmalloc-64(1972:pac4cli.service)"
Nov 28 10:37:09 systemd[1]: pac4cli.service: Service hold-off time over, scheduling restart.
Nov 28 10:37:09 systemd[1]: pac4cli.service: Scheduled restart job, restart counter is at 1.
Nov 28 10:37:09 systemd[1]: Stopped PAC autoconfigured proxy for use through http_proxy= environment variables.
Nov 28 10:37:09 systemd[1]: Started PAC autoconfigured proxy for use through http_proxy= environment variables.
Nov 28 10:37:10 systemd-resolved[860]: Server returned error NXDOMAIN, mitigating potential DNS violation DVE-2018-0001, retrying transaction with reduced feature level UDP.
Nov 28 10:37:11 systemd-resolved[860]: message repeated 3 times: [ Server returned error NXDOMAIN, mitigating potential DNS violation DVE-2018-0001, retrying transaction with reduced feature level UDP.]
Nov 28 10:38:05 pac4cli[3788]: Unhandled Error
Nov 28 10:38:05 pac4cli[3788]: Traceback (most recent call last):
Nov 28 10:38:05 pac4cli[3788]: File "/usr/lib/python3.6/runpy.py", line 85, in _run_code
Nov 28 10:38:05 pac4cli[3788]: exec(code, run_globals)
Nov 28 10:38:05 pac4cli[3788]: File "/usr/lib/python3/dist-packages/pac4cli/__main__.py", line 145, in <module>
Nov 28 10:38:05 pac4cli[3788]: reactor.run()
Nov 28 10:38:05 pac4cli[3788]: File "/usr/lib/python3/dist-packages/twisted/internet/base.py", line 1243, in run
Nov 28 10:38:05 pac4cli[3788]: self.mainLoop()
Nov 28 10:38:05 pac4cli[3788]: File "/usr/lib/python3/dist-packages/twisted/internet/base.py", line 1252, in mainLoop
Nov 28 10:38:05 pac4cli[3788]: self.runUntilCurrent()
Nov 28 10:38:05 pac4cli[3788]: --- <exception caught here> ---
Nov 28 10:38:05 pac4cli[3788]: File "/usr/lib/python3/dist-packages/twisted/internet/base.py", line 851, in runUntilCurrent
Nov 28 10:38:05 pac4cli[3788]: f(*a, **kw)
Nov 28 10:38:05 pac4cli[3788]: File "/usr/lib/python3/dist-packages/twisted/internet/base.py", line 627, in stop
Nov 28 10:38:05 pac4cli[3788]: "Can't stop reactor that isn't running.")
Nov 28 10:38:05 pac4cli[3788]: twisted.internet.error.ReactorNotRunning: Can't stop reactor that isn't running.
Nov 28 10:38:05 pac4cli[3788]: ['127.0.0.1']
Nov 28 10:38:05 systemd[1]: pac4cli.service: Service hold-off time over, scheduling restart.
Nov 28 10:38:05 systemd[1]: pac4cli.service: Scheduled restart job, restart counter is at 2.
Nov 28 10:38:05 systemd[1]: Stopped PAC autoconfigured proxy for use through http_proxy= environment variables.
Nov 28 10:38:05 systemd[1]: Started PAC autoconfigured proxy for use through http_proxy= environment variables.
Nov 28 10:38:06 systemd-resolved[860]: Server returned error NXDOMAIN, mitigating potential DNS violation DVE-2018-0001, retrying transaction with reduced feature level UDP.
Nov 28 10:38:06 systemd-resolved[860]: Server returned error NXDOMAIN, mitigating potential DNS violation DVE-2018-0001, retrying transaction with reduced feature level UDP.
When I looked at running processes (using htop), I noticed there were several instances of pac4cli running.
I suspect pac4cli crashed somehow or just misbehaved, and then systemd (or something else) spawned a new process, which also crashed, which spawned a new process… Until I had about a dozen pac4cli processes and then the entire system started to degenerate with The maximum number of active connections for UID 0 has been reached messages.
Nov 28 10:22:29 dbus-daemon[1128]: [system] Connection has not authenticated soon enough, closing it (auth_timeout=30000ms, elapsed: 30002ms)
Nov 28 10:22:31 dbus-daemon[1128]: [system] Connection has not authenticated soon enough, closing it (auth_timeout=30000ms, elapsed: 30001ms)
Nov 28 10:22:33 NetworkManager[1187]: <info> [1543396953.2148] audit: op="connection-activate" uuid="…" name="…" pid=2249 uid=1000 result="success"
Nov 28 10:22:33 NetworkManager[1187]: <info> [1543396953.2242] vpn-connection[0x55f59cc0c500,…,"…",0]: Started the VPN service, PID 310
Nov 28 10:22:33 dbus-daemon[1128]: [system] The maximum number of active connections for UID 0 has been reached (max_connections_per_user=256)
Nov 28 10:22:35 dbus-daemon[1128]: [system] Connection has not authenticated soon enough, closing it (auth_timeout=30000ms, elapsed: 30002ms)
Nov 28 10:22:37 NetworkManager[1187]: <warn> [1543396957.9902] vpn-connection[0x55f59cc0c500,…,"…",0]: Timed out waiting for the service to start
Nov 28 10:22:38 dbus-daemon[1128]: [system] Connection has not authenticated soon enough, closing it (auth_timeout=30000ms, elapsed: 30001ms)
Nov 28 10:22:38 dbus-daemon[1128]: [system] Connection has not authenticated soon enough, closing it (auth_timeout=30000ms, elapsed: 30000ms)
Nov 28 10:22:38 dbus-daemon[1128]: [system] Connection has not authenticated soon enough, closing it (auth_timeout=30000ms, elapsed: 30000ms)
Nov 28 10:22:46 NetworkManager[1187]: <info> [1543396966.3281] audit: op="connection-activate" uuid="…" name="…" pid=2249 uid=1000 result="success"
Nov 28 10:22:46 NetworkManager[1187]: <info> [1543396966.3683] vpn-connection[0x55f59cc0c700,…,"…",0]: Started the VPN service, PID 317
Nov 28 10:22:46 dbus-daemon[1128]: [system] The maximum number of active connections for UID 0 has been reached (max_connections_per_user=256)
Nov 28 10:22:51 NetworkManager[1187]: <warn> [1543396971.9913] vpn-connection[0x55f59cc0c700,…,"…",0]: Timed out waiting for the service to start
Nov 28 10:23:23 NetworkManager[1187]: <info> [1543397003.2327] audit: op="connection-activate" uuid="…" name="…" pid=2249 uid=1000 result="success"
Nov 28 10:23:23 NetworkManager[1187]: <info> [1543397003.2470] vpn-connection[0x55f59cc0c700,…,"…",0]: Started the VPN service, PID 389
Nov 28 10:23:23 dbus-daemon[1128]: [system] The maximum number of active connections for UID 0 has been reached (max_connections_per_user=256)
Nov 28 10:23:28 NetworkManager[1187]: <warn> [1543397008.9916] vpn-connection[0x55f59cc0c700,…,"…",0]: Timed out waiting for the service to start
Nov 28 10:27:01 dbus-daemon[1128]: [system] Activating service name='org.debian.apt' requested by ':1.1004' (uid=1000 pid=535 comm="/usr/bin/python3 /usr/bin/update-manager " label="unconfined") (using servicehelper)
Nov 28 10:27:02 AptDaemon: INFO: Initializing daemon
Nov 28 10:27:02 org.debian.apt[1128]: 10:27:02 AptDaemon [INFO]: Initializing daemon
Nov 28 10:27:02 dbus-daemon[1128]: [system] The maximum number of active connections for UID 0 has been reached (max_connections_per_user=256)
Nov 28 10:27:02 org.debian.apt[1128]: Traceback (most recent call last):
Nov 28 10:27:02 org.debian.apt[1128]: File "/usr/sbin/aptd", line 39, in <module>
Nov 28 10:27:02 org.debian.apt[1128]: aptdaemon.core.main()
Nov 28 10:27:02 org.debian.apt[1128]: File "/usr/lib/python3/dist-packages/aptdaemon/core.py", line 2178, in main
Nov 28 10:27:02 org.debian.apt[1128]: daemon = AptDaemon(options, bus=bus)
Nov 28 10:27:02 org.debian.apt[1128]: File "/usr/lib/python3/dist-packages/aptdaemon/core.py", line 1416, in __init__
Nov 28 10:27:02 org.debian.apt[1128]: bus = dbus.SystemBus()
Nov 28 10:27:02 org.debian.apt[1128]: File "/usr/lib/python3/dist-packages/dbus/_dbus.py", line 194, in __new__
Nov 28 10:27:02 org.debian.apt[1128]: private=private)
Nov 28 10:27:02 org.debian.apt[1128]: File "/usr/lib/python3/dist-packages/dbus/_dbus.py", line 100, in __new__
Nov 28 10:27:02 org.debian.apt[1128]: bus = BusConnection.__new__(subclass, bus_type, mainloop=mainloop)
Nov 28 10:27:02 org.debian.apt[1128]: File "/usr/lib/python3/dist-packages/dbus/bus.py", line 122, in __new__
Nov 28 10:27:02 org.debian.apt[1128]: bus = cls._new_for_bus(address_or_type, mainloop=mainloop)
Nov 28 10:27:02 org.debian.apt[1128]: dbus.exceptions.DBusException: org.freedesktop.DBus.Error.LimitsExceeded: The maximum number of active connections for UID 0 has been reached
Nov 28 10:27:02 dbus-daemon[1128]: [system] Activated service 'org.debian.apt' failed: Launch helper exited with unknown return code 1
Nov 28 10:27:41 dbus-daemon[1128]: [system] The maximum number of active connections for UID 0 has been reached (max_connections_per_user=256)
Nov 28 10:29:57 dbus-daemon[1128]: [system] Reloaded configuration
Nov 28 10:29:58 systemd[1]: Reexecuting.
Nov 28 10:29:58 kernel: [373387.899583] systemd: 35 output lines suppressed due to ratelimiting
Nov 28 10:29:58 kernel: [373387.908379] systemd[1]: systemd 237 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid)
Nov 28 10:29:58 kernel: [373387.908807] systemd[1]: Detected architecture x86-64.
Nov 28 10:29:58 dbus-daemon[1128]: [system] The maximum number of active connections for UID 0 has been reached (max_connections_per_user=256)
Nov 28 10:29:58 kernel: [373387.968634] systemd[1]: Failed to get initial list of names: No buffer space available
Nov 28 10:29:58 kernel: [373387.968640] systemd[1]: Failed to set up API bus: No buffer space available
Nov 28 10:29:58 kernel: [373387.968644] systemd[1]: Error occured during D-Bus APIs initialization: No buffer space available
Nov 28 10:29:58 kernel: [373387.968734] systemd[1]: Failed to register Manager vtable: File exists
Nov 28 10:29:58 kernel: [373387.968737] systemd[1]: Failed to set up API bus: File exists
Nov 28 10:29:58 kernel: [373387.968740] systemd[1]: Error occured during D-Bus APIs initialization: File exists
Nov 28 10:29:58 systemd[1]: Starting resolvconf-pull-resolved.service...
Nov 28 10:29:58 systemd[1]: Started resolvconf-pull-resolved.service.
Nov 28 10:30:02 dbus-daemon[1128]: [system] The maximum number of active connections for UID 0 has been reached (max_connections_per_user=256)
Nov 28 10:35:36 dbus-daemon[1128]: [system] The maximum number of active connections for UID 0 has been reached (max_connections_per_user=256)
Nov 28 10:36:06 dbus-daemon[1128]: [system] Connection has not authenticated soon enough, closing it (auth_timeout=30000ms, elapsed: 30003ms)
Nov 28 10:36:06 dbus-daemon[1128]: [system] The maximum number of active connections for UID 0 has been reached (max_connections_per_user=256)
Nov 28 10:36:36 dbus-daemon[1128]: [system] Connection has not authenticated soon enough, closing it (auth_timeout=30000ms, elapsed: 30000ms)
Nov 28 10:36:36 dbus-daemon[1128]: [system] The maximum number of active connections for UID 0 has been reached (max_connections_per_user=256)
At that point, I couldn't start/stop/restart services, some stuff just did not work (e.g. apt upgrade just hung when trying to update grub, and OpenVPN failed to connect), and I had to restart the entire system.
denilsonsa commented
It happened again right now. I cannot connect to VPN, I see errors on syslog, but this time htop is only showing two pac4cli processes: /bin/sh /usr/bin/pac4cli and /usr/bin/python3 -m pac4cli.
Dec 6 13:08:21 pac4cli[31330]: Unhandled Error
Dec 6 13:08:21 pac4cli[31330]: Traceback (most recent call last):
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/python/log.py", line 103, in callWithLogger
Dec 6 13:08:21 pac4cli[31330]: return callWithContext({"system": lp}, func, *args, **kw)
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/python/log.py", line 86, in callWithContext
Dec 6 13:08:21 pac4cli[31330]: return context.call({ILogContext: newCtx}, func, *args, **kw)
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/python/context.py", line 122, in callWithContext
Dec 6 13:08:21 pac4cli[31330]: return self.currentContext().callWithContext(ctx, func, *args, **kw)
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/python/context.py", line 85, in callWithContext
Dec 6 13:08:21 pac4cli[31330]: return func(*args,**kw)
Dec 6 13:08:21 pac4cli[31330]: --- <exception caught here> ---
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/internet/posixbase.py", line 614, in _doReadOrWrite
Dec 6 13:08:21 pac4cli[31330]: why = selectable.doRead()
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/internet/tcp.py", line 205, in doRead
Dec 6 13:08:21 pac4cli[31330]: return self._dataReceived(data)
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/internet/tcp.py", line 211, in _dataReceived
Dec 6 13:08:21 pac4cli[31330]: rval = self.protocol.dataReceived(data)
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/protocols/basic.py", line 578, in dataReceived
Dec 6 13:08:21 pac4cli[31330]: why = self.rawDataReceived(data)
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/web/http.py", line 631, in rawDataReceived
Dec 6 13:08:21 pac4cli[31330]: self.handleResponsePart(data)
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/web/proxy.py", line 77, in handleResponsePart
Dec 6 13:08:21 pac4cli[31330]: self.father.write(buffer)
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/web/http.py", line 1084, in write
Dec 6 13:08:21 pac4cli[31330]: self.channel.writeSequence(toChunk(data))
Dec 6 13:08:21 pac4cli[31330]: builtins.AttributeError: 'NoneType' object has no attribute 'writeSequence'
Dec 6 13:08:21 pac4cli[31330]: Unhandled Error
Dec 6 13:08:21 pac4cli[31330]: Traceback (most recent call last):
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/pac4cli/__main__.py", line 121, in <module>
Dec 6 13:08:21 pac4cli[31330]: reactor.run()
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/internet/base.py", line 1243, in run
Dec 6 13:08:21 pac4cli[31330]: self.mainLoop()
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/internet/base.py", line 1255, in mainLoop
Dec 6 13:08:21 pac4cli[31330]: self.doIteration(t)
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/internet/epollreactor.py", line 235, in doPoll
Dec 6 13:08:21 pac4cli[31330]: log.callWithLogger(selectable, _drdw, selectable, fd, event)
Dec 6 13:08:21 pac4cli[31330]: --- <exception caught here> ---
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/python/log.py", line 103, in callWithLogger
Dec 6 13:08:21 pac4cli[31330]: return callWithContext({"system": lp}, func, *args, **kw)
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/python/log.py", line 86, in callWithContext
Dec 6 13:08:21 pac4cli[31330]: return context.call({ILogContext: newCtx}, func, *args, **kw)
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/python/context.py", line 122, in callWithContext
Dec 6 13:08:21 pac4cli[31330]: return self.currentContext().callWithContext(ctx, func, *args, **kw)
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/python/context.py", line 85, in callWithContext
Dec 6 13:08:21 pac4cli[31330]: return func(*args,**kw)
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/internet/posixbase.py", line 627, in _doReadOrWrite
Dec 6 13:08:21 pac4cli[31330]: self._disconnectSelectable(selectable, why, inRead)
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/internet/posixbase.py", line 258, in _disconnectSelectable
Dec 6 13:08:21 pac4cli[31330]: selectable.connectionLost(failure.Failure(why))
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/internet/tcp.py", line 475, in connectionLost
Dec 6 13:08:21 pac4cli[31330]: self._commonConnection.connectionLost(self, reason)
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/internet/tcp.py", line 289, in connectionLost
Dec 6 13:08:21 pac4cli[31330]: protocol.connectionLost(reason)
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/web/http.py", line 585, in connectionLost
Dec 6 13:08:21 pac4cli[31330]: self.handleResponseEnd()
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/web/proxy.py", line 87, in handleResponseEnd
Dec 6 13:08:21 pac4cli[31330]: self.father.finish()
Dec 6 13:08:21 pac4cli[31330]: File "/usr/lib/python3/dist-packages/twisted/web/http.py", line 992, in finish
Dec 6 13:08:21 pac4cli[31330]: "Request.finish called on a request after its connection was lost; "
Dec 6 13:08:21 pac4cli[31330]: builtins.RuntimeError: Request.finish called on a request after its connection was lost; use Request.notifyFinish to keep track of this.
Dec 6 17:38:22 systemd[1]: Reached target Sleep.
Dec 6 17:38:22 systemd[1]: Starting Suspend...
Dec 6 17:38:22 systemd-sleep[16288]: Suspending system...
Dec 6 17:38:22 kernel: [110954.634441] PM: suspend entry (deep)
Dec 6 17:38:22 /usr/lib/python3/dist-packages/pac4cli/__main__.py[31333]: WARNING [31333]: pac4cli: Problem getting wpad option for connection /org/freedesktop/NetworkManager/ActiveConnection/22#012Traceback (most recent call last):#012 File "/usr/lib/python3/dist-packages/pac4cli/wpad.py", line 84, in get_wpad_url#012 'org.freedesktop.NetworkManager.Connection.Active', 'Dhcp4Config')#012txdbus.error.RemoteError: org.freedesktop.DBus.Error.UnknownMethod: No such interface 'org.freedesktop.DBus.Properties' on object at path /org/freedesktop/NetworkManager/ActiveConnection/22
Dec 6 17:38:28 kernel: [110954.634443] PM: Syncing filesystems ... done.
The laptop went to sleep, and then I brought it out of the corp network and into a home network.
Dec 6 22:22:06 /usr/lib/python3/dist-packages/pac4cli/__main__.py[31333]: WARNING [31333]: pac4cli: Problem getting wpad option for connection /org/freedesktop/NetworkManager/ActiveConnection/23#012Traceback (most recent call last):#012 File "/usr/lib/python3/dist-packages/pac4cli/wpad.py", line 84, in get_wpad_url#012 'org.freedesktop.NetworkManager.Connection.Active', 'Dhcp4Config')#012txdbus.error.RemoteError: org.freedesktop.DBus.Error.UnknownMethod: No such interface 'org.freedesktop.DBus.Properties' on object at path /org/freedesktop/NetworkManager/ActiveConnection/23
…
Dec 6 22:22:06 NetworkManager[1172]: <info> [1544131326.2102] manager: sleep: wake requested (sleeping: yes enabled: yes)
…
Dec 6 22:22:06 dbus-daemon[1129]: [system] The maximum number of active connections for UID 0 has been reached (max_connections_per_user=256)
Dec 6 22:22:06 /usr/lib/python3/dist-packages/pac4cli/__main__.py[31333]: WARNING [31333]: pac4cli: Issue getting wpad configuration#012Traceback (most recent call last):#012 File "/usr/lib/python3/dist-packages/pac4cli/__main__.py", line 46, in get_possible_configuration_locations#012 urls = yield wpad.getUrls()#012txdbus.error.RemoteError: org.freedesktop.DBus.Error.LimitsExceeded: The maximum number of active connections for UID 0 has been reached
Dec 6 22:22:06 wpa_supplicant[1171]: dbus: fill_dict_with_properties dbus_interface=fi.w1.wpa_supplicant1.Interface dbus_property=Stations getter failed
Dec 6 22:22:06 wpa_supplicant[1171]: dbus: wpa_dbus_get_object_properties: failed to get object properties: (none) none
Dec 6 22:22:06 wpa_supplicant[1171]: dbus: Failed to construct signal
Dec 6 22:22:06 wpa_supplicant[1171]: dbus: fill_dict_with_properties dbus_interface=fi.w1.wpa_supplicant1.Interface dbus_property=Stations getter failed
Then I tried running systemctl stop pac4cli.
And it worked! pac4cli was no longer running, and I could connect to VPN just fine.
Thus, I suspect two causes:
- pac4cli crashes or misbehaves and multiple processes are launched in parallel (that's likely what happened another day).
- pac4cli is creating too many dbus connections (that's what is happening today).
tkluck commented
Hey @denilsonsa , sorry for letting this languish.
I don't really understand what gets pac4cli in this situation. It seems that many Deferreds are being created with each their own connection to dbus. If they linger instead of terminating, this would cause this symptom.
Re-using the dbus connection between them should prevent whatever error condition leads to this pile-up from overloading the system in the way you've observed. I implemented that in #58. Do you have any thoughts about that approach?
Of course, that's no substitute for actually understanding and fixing the cause of the pile-up. It likely remains as a (hopefully less fatal) memory leak.
tkluck commented
This pull request should also help system stability, as it will not be the root user that runs out of dbus connections.
claudiocolaluce commented
Hi guys,
I have the same problem.
When I run the command: firewall-cmd --list-ports
I receive as a result: dbus_error: the maximum number of active connections for uid 0 has been reached
My system is a Centos 7.
With root user