Join GitHub today
GitHub is home to over 28 million developers working together to host and review code, manage projects, and build software together.
Sign upUpdate proxy ceases to work after suspend / resume #3135
Comments
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
marmarek
Sep 29, 2017
Member
Can you check logs about qubes-updates-proxy.service when it fails? journalctl -u qubes-updates-proxy.service
|
Can you check logs about qubes-updates-proxy.service when it fails? |
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
vincentadultman
Sep 29, 2017
Sure:
Sep 29 17:29:07 sys-net systemd[1]: qubes-updates-proxy.service: Start request repeated too quickly.
Sep 29 17:29:07 sys-net systemd[1]: Failed to start Qubes updates proxy (tinyproxy).
Sep 29 17:29:07 sys-net systemd[1]: qubes-updates-proxy.service: Unit entered failed state.
Sep 29 17:29:07 sys-net systemd[1]: qubes-updates-proxy.service: Failed with result 'start-limit-hit'.
I presume here the times shown are from before the clock has synced up after the suspend, as otherwise nothing would appear for the relevant time of resume (two hours after whats shown above)
vincentadultman
commented
Sep 29, 2017
|
Sure: Sep 29 17:29:07 sys-net systemd[1]: qubes-updates-proxy.service: Start request repeated too quickly. I presume here the times shown are from before the clock has synced up after the suspend, as otherwise nothing would appear for the relevant time of resume (two hours after whats shown above) |
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
marmarek
Sep 29, 2017
Member
Anything earlier? If there was "Start request", there must be some event that stopped that service in the first place...
|
Anything earlier? If there was "Start request", there must be some event that stopped that service in the first place... |
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
vincentadultman
Sep 29, 2017
Included all today's lines. I'm unsure of the cause of the hostname sometimes being shown as "Unknown-58-94-6b-9e-51-58-3" this is also the output of the "hostname" command in sys-net all of the time that I've seen, think that started when template for this vm was switched from fedora-24-minimal to fedora-25-minimal, but couldn't swear to that...
Sep 29 07:36:20 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 29 07:36:20 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 29 07:36:20 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 29 07:36:20 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 29 07:36:21 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 29 07:36:21 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 29 07:36:21 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 29 07:36:21 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 29 07:36:21 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 29 07:36:21 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 29 07:36:21 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 29 07:36:21 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 29 08:07:20 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 29 08:07:20 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 29 08:07:20 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 29 08:07:20 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 29 08:07:20 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 29 08:07:20 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 29 08:07:20 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 29 08:07:20 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 29 08:07:20 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 29 08:07:20 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 29 08:07:20 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 29 08:07:20 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 29 08:07:20 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 29 08:07:20 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 29 08:07:20 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 29 08:07:20 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 29 08:07:21 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 29 08:07:21 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 29 08:07:21 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 29 08:07:21 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 29 08:07:21 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 29 08:07:21 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 29 08:07:21 sys-net systemd[1]: qubes-updates-proxy.service: Start request repeated too quickly.
Sep 29 08:07:21 sys-net systemd[1]: Failed to start Qubes updates proxy (tinyproxy).
Sep 29 08:07:21 sys-net systemd[1]: qubes-updates-proxy.service: Unit entered failed state.
Sep 29 08:07:21 sys-net systemd[1]: qubes-updates-proxy.service: Failed with result 'start-limit-hit'.
Sep 29 16:46:10 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 29 16:46:10 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 29 16:46:30 Unknown-58-94-6b-9e-51-58-3 tinyproxy[12351]: Waiting servers (0) is less than MinSpareServers (2). Creating new child.
Sep 29 16:46:35 Unknown-58-94-6b-9e-51-58-3 tinyproxy[12351]: Waiting servers (0) is less than MinSpareServers (2). Creating new child.
Sep 29 17:12:25 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 29 17:12:25 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 29 17:12:25 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 29 17:12:25 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 29 17:12:25 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 29 17:12:25 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 29 17:12:25 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 29 17:12:25 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 29 17:12:26 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 29 17:12:26 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 29 17:12:26 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 29 17:12:26 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 29 17:12:26 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 29 17:12:26 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 29 17:12:26 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 29 17:12:26 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 29 17:12:26 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 29 17:12:26 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 29 17:12:26 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 29 17:12:26 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 29 17:12:26 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 29 17:12:26 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 29 17:12:26 sys-net systemd[1]: qubes-updates-proxy.service: Start request repeated too quickly.
Sep 29 17:12:26 sys-net systemd[1]: Failed to start Qubes updates proxy (tinyproxy).
Sep 29 17:12:26 sys-net systemd[1]: qubes-updates-proxy.service: Unit entered failed state.
Sep 29 17:12:26 sys-net systemd[1]: qubes-updates-proxy.service: Failed with result 'start-limit-hit'.
Sep 29 17:18:08 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 29 17:18:08 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 29 17:18:38 Unknown-58-94-6b-9e-51-58-3 tinyproxy[13638]: Waiting servers (1) is less than MinSpareServers (2). Creating new child.
Sep 29 17:18:43 Unknown-58-94-6b-9e-51-58-3 tinyproxy[13638]: Waiting servers (0) is less than MinSpareServers (2). Creating new child.
Sep 29 17:29:06 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 29 17:29:06 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 29 17:29:06 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 29 17:29:06 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 29 17:29:06 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 29 17:29:06 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 29 17:29:06 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 29 17:29:06 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 29 17:29:06 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 29 17:29:06 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 29 17:29:06 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 29 17:29:06 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 29 17:29:07 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 29 17:29:07 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 29 17:29:07 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 29 17:29:07 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 29 17:29:07 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 29 17:29:07 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 29 17:29:07 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 29 17:29:07 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 29 17:29:07 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 29 17:29:07 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 29 17:29:07 sys-net systemd[1]: qubes-updates-proxy.service: Start request repeated too quickly.
vincentadultman
commented
Sep 29, 2017
|
Included all today's lines. I'm unsure of the cause of the hostname sometimes being shown as "Unknown-58-94-6b-9e-51-58-3" this is also the output of the "hostname" command in sys-net all of the time that I've seen, think that started when template for this vm was switched from fedora-24-minimal to fedora-25-minimal, but couldn't swear to that... Sep 29 07:36:20 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)... |
andrewdavidwong
added
bug
C: core
labels
Sep 30, 2017
andrewdavidwong
added this to the Release 3.2 updates milestone
Sep 30, 2017
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
vincentadultman
Sep 30, 2017
And for completeness, with log level turned from "notice" to "info". The below comprises a normal restart of tinyproxy for the syntax change, and then a suspend / resume
Sep 30 10:13:15 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 30 10:13:15 Unknown-58-94-6b-9e-51-58-3 systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 30 10:13:15 Unknown-58-94-6b-9e-51-58-3 tinyproxy[19591]: Initializing tinyproxy ...
Sep 30 10:13:15 Unknown-58-94-6b-9e-51-58-3 tinyproxy[19591]: Reloading config file
Sep 30 10:13:15 Unknown-58-94-6b-9e-51-58-3 tinyproxy[19591]: Disabling transmission of the "Via" header.
Sep 30 10:13:15 Unknown-58-94-6b-9e-51-58-3 tinyproxy[19591]: Adding Port [443] to the list allowed by CONNECT
Sep 30 10:13:15 Unknown-58-94-6b-9e-51-58-3 tinyproxy[19591]: Now running as group "tinyproxy".
Sep 30 10:13:15 Unknown-58-94-6b-9e-51-58-3 tinyproxy[19591]: Now running as user "tinyproxy".
Sep 30 10:13:15 Unknown-58-94-6b-9e-51-58-3 tinyproxy[19591]: Creating child number 1 of 2 ...
Sep 30 10:13:15 Unknown-58-94-6b-9e-51-58-3 tinyproxy[19591]: Creating child number 2 of 2 ...
Sep 30 10:13:15 Unknown-58-94-6b-9e-51-58-3 tinyproxy[19591]: Finished creating all children.
Sep 30 10:13:15 Unknown-58-94-6b-9e-51-58-3 tinyproxy[19591]: Setting the various signals.
Sep 30 10:13:15 Unknown-58-94-6b-9e-51-58-3 tinyproxy[19591]: Starting main loop. Accepting connections.
Sep 30 10:14:15 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 30 10:14:15 sys-net tinyproxy[19591]: Shutting down.
Sep 30 10:14:15 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 30 10:14:15 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 30 10:14:15 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 30 10:14:15 sys-net tinyproxy[19750]: Initializing tinyproxy ...
Sep 30 10:14:15 sys-net tinyproxy[19750]: Reloading config file
Sep 30 10:14:15 sys-net tinyproxy[19750]: Disabling transmission of the "Via" header.
Sep 30 10:14:15 sys-net tinyproxy[19750]: Adding Port [443] to the list allowed by CONNECT
Sep 30 10:14:15 sys-net tinyproxy[19750]: Now running as group "tinyproxy".
Sep 30 10:14:15 sys-net tinyproxy[19750]: Now running as user "tinyproxy".
Sep 30 10:14:15 sys-net tinyproxy[19750]: Creating child number 1 of 2 ...
Sep 30 10:14:15 sys-net tinyproxy[19750]: Creating child number 2 of 2 ...
Sep 30 10:14:15 sys-net tinyproxy[19750]: Finished creating all children.
Sep 30 10:14:15 sys-net tinyproxy[19750]: Setting the various signals.
Sep 30 10:14:15 sys-net tinyproxy[19750]: Starting main loop. Accepting connections.
Sep 30 10:14:15 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 30 10:14:15 sys-net tinyproxy[19750]: Shutting down.
Sep 30 10:14:15 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 30 10:14:15 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 30 10:14:15 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 30 10:14:15 sys-net tinyproxy[19792]: Initializing tinyproxy ...
Sep 30 10:14:15 sys-net tinyproxy[19792]: Reloading config file
Sep 30 10:14:15 sys-net tinyproxy[19792]: Disabling transmission of the "Via" header.
Sep 30 10:14:15 sys-net tinyproxy[19792]: Adding Port [443] to the list allowed by CONNECT
Sep 30 10:14:15 sys-net tinyproxy[19792]: Now running as group "tinyproxy".
Sep 30 10:14:15 sys-net tinyproxy[19792]: Now running as user "tinyproxy".
Sep 30 10:14:15 sys-net tinyproxy[19792]: Creating child number 1 of 2 ...
Sep 30 10:14:15 sys-net tinyproxy[19792]: Creating child number 2 of 2 ...
Sep 30 10:14:15 sys-net tinyproxy[19792]: Finished creating all children.
Sep 30 10:14:15 sys-net tinyproxy[19792]: Setting the various signals.
Sep 30 10:14:15 sys-net tinyproxy[19792]: Starting main loop. Accepting connections.
Sep 30 10:14:15 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 30 10:14:16 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 30 10:14:16 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 30 10:14:16 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 30 10:14:16 sys-net tinyproxy[19826]: Initializing tinyproxy ...
Sep 30 10:14:16 sys-net tinyproxy[19826]: Reloading config file
Sep 30 10:14:16 sys-net tinyproxy[19826]: Disabling transmission of the "Via" header.
Sep 30 10:14:16 sys-net tinyproxy[19826]: Adding Port [443] to the list allowed by CONNECT
Sep 30 10:14:16 sys-net tinyproxy[19826]: Now running as group "tinyproxy".
Sep 30 10:14:16 sys-net tinyproxy[19826]: Now running as user "tinyproxy".
Sep 30 10:14:16 sys-net tinyproxy[19826]: Creating child number 1 of 2 ...
Sep 30 10:14:16 sys-net tinyproxy[19826]: Creating child number 2 of 2 ...
Sep 30 10:14:16 sys-net tinyproxy[19826]: Finished creating all children.
Sep 30 10:14:16 sys-net tinyproxy[19826]: Setting the various signals.
Sep 30 10:14:16 sys-net tinyproxy[19826]: Starting main loop. Accepting connections.
Sep 30 10:14:16 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 30 10:14:16 sys-net tinyproxy[19826]: Shutting down.
Sep 30 10:14:16 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 30 10:14:16 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 30 10:14:16 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 30 10:14:16 sys-net tinyproxy[19867]: Initializing tinyproxy ...
Sep 30 10:14:16 sys-net tinyproxy[19867]: Reloading config file
Sep 30 10:14:16 sys-net tinyproxy[19867]: Disabling transmission of the "Via" header.
Sep 30 10:14:16 sys-net tinyproxy[19867]: Adding Port [443] to the list allowed by CONNECT
Sep 30 10:14:16 sys-net tinyproxy[19867]: Now running as group "tinyproxy".
Sep 30 10:14:16 sys-net tinyproxy[19867]: Now running as user "tinyproxy".
Sep 30 10:14:16 sys-net tinyproxy[19867]: Creating child number 1 of 2 ...
Sep 30 10:14:16 sys-net tinyproxy[19867]: Creating child number 2 of 2 ...
Sep 30 10:14:16 sys-net tinyproxy[19867]: Finished creating all children.
Sep 30 10:14:16 sys-net tinyproxy[19867]: Setting the various signals.
Sep 30 10:14:16 sys-net tinyproxy[19867]: Starting main loop. Accepting connections.
Sep 30 10:14:16 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 30 10:14:16 sys-net tinyproxy[19867]: Shutting down.
Sep 30 10:14:16 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 30 10:14:16 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Sep 30 10:14:16 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Sep 30 10:14:16 sys-net tinyproxy[19917]: Initializing tinyproxy ...
Sep 30 10:14:16 sys-net tinyproxy[19917]: Reloading config file
Sep 30 10:14:16 sys-net tinyproxy[19917]: Disabling transmission of the "Via" header.
Sep 30 10:14:16 sys-net tinyproxy[19917]: Adding Port [443] to the list allowed by CONNECT
Sep 30 10:14:16 sys-net tinyproxy[19917]: Now running as group "tinyproxy".
Sep 30 10:14:16 sys-net tinyproxy[19917]: Now running as user "tinyproxy".
Sep 30 10:14:16 sys-net tinyproxy[19917]: Creating child number 1 of 2 ...
Sep 30 10:14:16 sys-net tinyproxy[19917]: Creating child number 2 of 2 ...
Sep 30 10:14:16 sys-net tinyproxy[19917]: Finished creating all children.
Sep 30 10:14:16 sys-net tinyproxy[19917]: Setting the various signals.
Sep 30 10:14:16 sys-net tinyproxy[19917]: Starting main loop. Accepting connections.
Sep 30 10:14:16 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Sep 30 10:14:16 sys-net tinyproxy[19917]: Shutting down.
Sep 30 10:14:16 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Sep 30 10:14:16 sys-net systemd[1]: qubes-updates-proxy.service: Start request repeated too quickly.
Sep 30 10:14:16 sys-net systemd[1]: Failed to start Qubes updates proxy (tinyproxy).
Sep 30 10:14:16 sys-net systemd[1]: qubes-updates-proxy.service: Unit entered failed state.
Sep 30 10:14:16 sys-net systemd[1]: qubes-updates-proxy.service: Failed with result 'start-limit-hit'.
vincentadultman
commented
Sep 30, 2017
|
And for completeness, with log level turned from "notice" to "info". The below comprises a normal restart of tinyproxy for the syntax change, and then a suspend / resume |
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
vincentadultman
Oct 3, 2017
It seems that the "qubes-updates-proxy.service: Failed with result 'start-limit-hit'" error could be related to the systemd service setting StartLimitInterval, insofar as setting StartLimitInterval=0 in /etc/systemd/system/multi-user.target.wants/qubes-updates-proxy.service and a "systemctl daemon-reload" prevents the problem with suspend resume (I've not modified this on the underlying template yet, but it works in running sys-net).
https://www.freedesktop.org/software/systemd/man/systemd.unit.html#StartLimitIntervalSec= says the following two things which suggests to me something is not behaving as it should, given setting the startlimitinterval to 0 resolve the problem (unless the doc is just poorly written, or I don't understand it on first pass)
"By default, units which are started more than 5 times within 10 seconds are not permitted to start any more times until the 10 second interval ends"
"Note that units which are configured for Restart= and which reach the start limit are not attempted to be restarted anymore; however, they may still be restarted manually at a later point, from which point on, the restart logic is again activated"
@marmarek can you actually reproduce the original issue on any of your machines? If not I'll reply to the thread on the mailing list to get more details from those getting the similar issue to see if they're actually getting the same error in their logs.
vincentadultman
commented
Oct 3, 2017
|
It seems that the "qubes-updates-proxy.service: Failed with result 'start-limit-hit'" error could be related to the systemd service setting StartLimitInterval, insofar as setting StartLimitInterval=0 in /etc/systemd/system/multi-user.target.wants/qubes-updates-proxy.service and a "systemctl daemon-reload" prevents the problem with suspend resume (I've not modified this on the underlying template yet, but it works in running sys-net). https://www.freedesktop.org/software/systemd/man/systemd.unit.html#StartLimitIntervalSec= says the following two things which suggests to me something is not behaving as it should, given setting the startlimitinterval to 0 resolve the problem (unless the doc is just poorly written, or I don't understand it on first pass) "By default, units which are started more than 5 times within 10 seconds are not permitted to start any more times until the 10 second interval ends" "Note that units which are configured for Restart= and which reach the start limit are not attempted to be restarted anymore; however, they may still be restarted manually at a later point, from which point on, the restart logic is again activated" @marmarek can you actually reproduce the original issue on any of your machines? If not I'll reply to the thread on the mailing list to get more details from those getting the similar issue to see if they're actually getting the same error in their logs. |
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
marmarek
Oct 3, 2017
Member
No, I have never hit it. But I suspect this trigger the problem. But normally NetworkManager shouldn't call this that often. Maybe broken network cable, or poor wifi?
|
No, I have never hit it. But I suspect this trigger the problem. But normally NetworkManager shouldn't call this that often. Maybe broken network cable, or poor wifi? |
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
oneaty
Dec 14, 2017
I confirm the issue the exact way it is described.
Follow a couple of log entries after resume.
Here, Qubes 3.2 is running on a Dell Inspiron N4050.
My workaround: as Bill says..
The entries:
(I closed the laptop lid at approximately 20:01)
Dec 14 19:59:32 N4050-wlan systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Dec 14 19:59:32 N4050-wlan systemd[1]: Started Qubes updates proxy (tinyproxy).
Dec 14 19:59:32 N4050-wlan systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Dec 14 19:59:32 N4050-wlan systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Dec 14 19:59:32 N4050-wlan systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Dec 14 19:59:32 N4050-wlan systemd[1]: Started Qubes updates proxy (tinyproxy).
Dec 14 19:59:32 N4050-wlan systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Dec 14 19:59:33 N4050-wlan systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Dec 14 19:59:33 N4050-wlan systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Dec 14 19:59:33 N4050-wlan systemd[1]: Started Qubes updates proxy (tinyproxy).
Dec 14 20:03:01 N4050-wlan systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Dec 14 20:03:01 N4050-wlan systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Dec 14 20:03:01 N4050-wlan systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Dec 14 20:03:01 N4050-wlan systemd[1]: Started Qubes updates proxy (tinyproxy).
Dec 14 20:03:01 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Dec 14 20:03:01 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Dec 14 20:03:01 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Dec 14 20:03:01 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Dec 14 20:03:37 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Dec 14 20:03:37 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Dec 14 20:03:37 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Dec 14 20:03:37 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Dec 14 20:03:38 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Dec 14 20:03:38 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Dec 14 20:03:38 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Dec 14 20:03:38 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Dec 14 20:03:38 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Dec 14 20:03:38 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Dec 14 20:03:38 sys-net systemd[1]: Starting Qubes updates proxy (tinyproxy)...
Dec 14 20:03:38 sys-net systemd[1]: Started Qubes updates proxy (tinyproxy).
Dec 14 20:03:38 sys-net systemd[1]: Stopping Qubes updates proxy (tinyproxy)...
Dec 14 20:03:38 sys-net systemd[1]: Stopped Qubes updates proxy (tinyproxy).
Dec 14 20:03:38 sys-net systemd[1]: qubes-updates-proxy.service: Start request repeated too quickly.
Dec 14 20:03:38 sys-net systemd[1]: Failed to start Qubes updates proxy (tinyproxy).
Dec 14 20:03:38 sys-net systemd[1]: qubes-updates-proxy.service: Unit entered failed state.
Dec 14 20:03:38 sys-net systemd[1]: qubes-updates-proxy.service: Failed with result 'start-limit-hit'.
oneaty
commented
Dec 14, 2017
•
edited
Edited 3 times
-
oneaty
edited Dec 15, 2017 (most recent)
-
oneaty
edited
Dec 15, 2017
-
oneaty
edited
Dec 14, 2017
edited
-
Dec 15, 2017 (most recent) -
Dec 15, 2017 -
Dec 14, 2017
|
I confirm the issue the exact way it is described. |
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
taradiddles
Jan 20, 2018
the problem is that qubes-nmhook is called on each NM event, which usually happen quickly in a row. This is shown by adding a debug statement like "echo $(date) $@ >> /tmp/d" to qubes-nmhook:
Sat Jan 20 10:07:55 EET 2018 connectivity-change
Sat Jan 20 10:07:55 EET 2018 wls5 down
Sat Jan 20 10:08:27 EET 2018 none hostname
Sat Jan 20 10:08:34 EET 2018 wls5 up
Sat Jan 20 10:08:34 EET 2018 none hostname
Sat Jan 20 10:08:35 EET 2018 connectivity-change
here the laptop is suspended at 10:07:55 and resumed ~30 seconds later. The hook is executed on each event - each time triggering a restart of the qubes-updates-proxy service. Systemd then gives up because the service is respawed too quickly; this is shown in journalctl:
systemd[1]: qubes-updates-proxy.service: Start request repeated too quickly.
systemd[1]: qubes-updates-proxy.service: Unit entered failed state.
systemd[1]: qubes-updates-proxy.service: Failed with result 'start-limit-hit'.
A workaround is to restart qubes-updates-proxy only on "interface up" event (see patch below). The sequence of events shown above might be different for other setups so the patch might not work everywhere. A better workaround may be to change the service's systemd "start-limit-hit", "Restart=on-failure", ... parameters.
(FYI this problem is still present in 4.0rc3).
--- qubes-nmhook.orig 2018-01-20 10:13:21.458304708 +0200
+++ qubes-nmhook 2018-01-20 10:15:37.991031014 +0200
@@ -7,8 +7,11 @@
/usr/lib/qubes/qubes-setup-dnat-to-ns
# FIXME: Tinyproxy does not reload DNS servers.
-if under_systemd ; then
- systemctl --no-block try-restart qubes-updates-proxy.service
-else
- service qubes-updates-proxy try-restart
+if [ "$2" = "up" ]; then
+ if under_systemd ; then
+ systemctl --no-block try-restart qubes-updates-proxy.service
+ else
+ service qubes-updates-proxy try-restart
+ fi
fi
[EDIT] : the patch above fixes the updates-proxy service but qubes-setup-dnat-to-ns should also probably be executed only on an "up" event - there's little use of executing it 3 times in a row.
taradiddles
commented
Jan 20, 2018
•
edited
Edited 2 times
-
taradiddles
edited Jan 23, 2018 (most recent)
-
taradiddles
edited
Jan 20, 2018
edited
-
Jan 23, 2018 (most recent) -
Jan 20, 2018
|
the problem is that qubes-nmhook is called on each NM event, which usually happen quickly in a row. This is shown by adding a debug statement like "echo $(date) $@ >> /tmp/d" to qubes-nmhook: here the laptop is suspended at 10:07:55 and resumed ~30 seconds later. The hook is executed on each event - each time triggering a restart of the qubes-updates-proxy service. Systemd then gives up because the service is respawed too quickly; this is shown in journalctl: A workaround is to restart qubes-updates-proxy only on "interface up" event (see patch below). The sequence of events shown above might be different for other setups so the patch might not work everywhere. A better workaround may be to change the service's systemd "start-limit-hit", "Restart=on-failure", ... parameters. (FYI this problem is still present in 4.0rc3). [EDIT] : the patch above fixes the updates-proxy service but qubes-setup-dnat-to-ns should also probably be executed only on an "up" event - there's little use of executing it 3 times in a row. |
andrewdavidwong
referenced this issue
Jan 23, 2018
Closed
qubes' suspend hooks aren't called after VM suspend/resume (so VM clock is out of sync) #3489
taradiddles
referenced this issue
Feb 9, 2018
Closed
"Error: failed to synchronize cache for repo ..." when using Fedora-26 as sys-net #3557
added a commit
to marmarek/qubes-core-agent-linux
that referenced
this issue
Feb 10, 2018
marmarek
referenced this issue
in QubesOS/qubes-core-agent-linux
Feb 10, 2018
Merged
network: reload DNS only on "up" event from NetworkManager #92
marmarek
closed this
in
QubesOS/qubes-core-agent-linux#92
Feb 13, 2018
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
qubesos-bot
Feb 13, 2018
Automated announcement from builder-github
The package qubes-core-agent_4.0.21-1+deb10u1 has been pushed to the r4.0 testing repository for the Debian template.
To test this update, first enable the testing repository in /etc/apt/sources.list.d/qubes-*.list by uncommenting the line containing buster-testing (or appropriate equivalent for your template version), then use the standard update command:
sudo apt-get update && sudo apt-get dist-upgrade
qubesos-bot
commented
Feb 13, 2018
|
Automated announcement from builder-github The package |
qubesos-bot
added
the
r4.0-buster-cur-test
label
Feb 13, 2018
qubesos-bot
referenced this issue
in QubesOS/updates-status
Feb 13, 2018
Closed
core-agent-linux v4.0.21 (r4.0) #410
qubesos-bot
added
the
r4.0-jessie-cur-test
label
Feb 13, 2018
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
qubesos-bot
Feb 13, 2018
Automated announcement from builder-github
The package qubes-core-agent_4.0.21-1+deb9u1 has been pushed to the r4.0 testing repository for the Debian template.
To test this update, first enable the testing repository in /etc/apt/sources.list.d/qubes-*.list by uncommenting the line containing stretch-testing (or appropriate equivalent for your template version), then use the standard update command:
sudo apt-get update && sudo apt-get dist-upgrade
qubesos-bot
commented
Feb 13, 2018
|
Automated announcement from builder-github The package |
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
qubesos-bot
Feb 13, 2018
Automated announcement from builder-github
The component core-agent-linux (including package python2-dnf-plugins-qubes-hooks-4.0.21-1.fc26) has been pushed to the r4.0 testing repository for the Fedora template.
To test this update, please install it with the following command:
sudo yum update --enablerepo=qubes-vm-r4.0-current-testing
qubesos-bot
commented
Feb 13, 2018
|
Automated announcement from builder-github The component |
qubesos-bot
added
the
r4.0-fc26-cur-test
label
Feb 13, 2018
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
qubesos-bot
Feb 13, 2018
Automated announcement from builder-github
The package core-agent-linux has been pushed to the r4.0 testing repository for the CentOS centos7 template.
To test this update, please install it with the following command:
sudo yum update --enablerepo=qubes-vm-r4.0-current-testing
qubesos-bot
commented
Feb 13, 2018
|
Automated announcement from builder-github The package |
qubesos-bot
added
the
r4.0-centos7-cur-test
label
Feb 13, 2018
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
qubesos-bot
Mar 12, 2018
Automated announcement from builder-github
The package core-agent-linux has been pushed to the r4.0 stable repository for the Fedora centos7 template.
To install this update, please use the standard update command:
sudo yum update
qubesos-bot
commented
Mar 12, 2018
|
Automated announcement from builder-github The package |
qubesos-bot
added
r4.0-centos7-stable
and removed
r4.0-centos7-cur-test
labels
Mar 12, 2018
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
qubesos-bot
Mar 12, 2018
Automated announcement from builder-github
The component core-agent-linux (including package python2-dnf-plugins-qubes-hooks-4.0.24-1.fc26) has been pushed to the r4.0 stable repository for the Fedora template.
To install this update, please use the standard update command:
sudo yum update
qubesos-bot
commented
Mar 12, 2018
|
Automated announcement from builder-github The component |
qubesos-bot
added
r4.0-fc26-stable
and removed
r4.0-fc26-cur-test
labels
Mar 12, 2018
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
qubesos-bot
Mar 12, 2018
Automated announcement from builder-github
The package qubes-core-agent_4.0.24-1+deb10u1 has been pushed to the r4.0 stable repository for the Debian template.
To install this update, please use the standard update command:
sudo apt-get update && sudo apt-get dist-upgrade
qubesos-bot
commented
Mar 12, 2018
|
Automated announcement from builder-github The package |
qubesos-bot
added
r4.0-buster-stable
r4.0-jessie-stable
and removed
r4.0-buster-cur-test
r4.0-jessie-cur-test
labels
Mar 12, 2018
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
qubesos-bot
Mar 12, 2018
Automated announcement from builder-github
The package qubes-core-agent_4.0.24-1+deb9u1 has been pushed to the r4.0 stable repository for the Debian template.
To install this update, please use the standard update command:
sudo apt-get update && sudo apt-get dist-upgrade
qubesos-bot
commented
Mar 12, 2018
|
Automated announcement from builder-github The package |
qubesos-bot
added
r4.0-stretch-stable
and removed
r4.0-stretch-cur-test
labels
Mar 12, 2018
added a commit
to marmarek/qubes-core-agent-linux
that referenced
this issue
Mar 21, 2018
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
qubesos-bot
Mar 22, 2018
Automated announcement from builder-github
The package qubes-core-agent_3.2.27-1+deb10u1 has been pushed to the r3.2 testing repository for the Debian template.
To test this update, first enable the testing repository in /etc/apt/sources.list.d/qubes-*.list by uncommenting the line containing buster-testing (or appropriate equivalent for your template version), then use the standard update command:
sudo apt-get update && sudo apt-get dist-upgrade
qubesos-bot
commented
Mar 22, 2018
|
Automated announcement from builder-github The package |
qubesos-bot
added
the
r3.2-buster-cur-test
label
Mar 22, 2018
qubesos-bot
referenced this issue
in QubesOS/updates-status
Mar 22, 2018
Closed
core-agent-linux v3.2.27 (r3.2) #463
qubesos-bot
added
the
r3.2-jessie-cur-test
label
Mar 22, 2018
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
qubesos-bot
Mar 22, 2018
Automated announcement from builder-github
The package qubes-core-agent_3.2.27-1+deb9u1 has been pushed to the r3.2 testing repository for the Debian template.
To test this update, first enable the testing repository in /etc/apt/sources.list.d/qubes-*.list by uncommenting the line containing stretch-testing (or appropriate equivalent for your template version), then use the standard update command:
sudo apt-get update && sudo apt-get dist-upgrade
qubesos-bot
commented
Mar 22, 2018
|
Automated announcement from builder-github The package |
qubesos-bot
added
r3.2-stretch-cur-test
r3.2-fc25-cur-test
labels
Mar 22, 2018
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
qubesos-bot
Mar 22, 2018
Automated announcement from builder-github
The component core-agent-linux (including package python2-dnf-plugins-qubes-hooks-3.2.27-1.fc26) has been pushed to the r3.2 testing repository for the Fedora template.
To test this update, please install it with the following command:
sudo yum update --enablerepo=qubes-vm-r3.2-current-testing
qubesos-bot
commented
Mar 22, 2018
|
Automated announcement from builder-github The component |
qubesos-bot
added
the
r3.2-fc26-cur-test
label
Mar 22, 2018
n1m1
referenced this issue
Mar 23, 2018
Closed
Fedora templates do not update the Qubes' repos through Whonix update proxy (R4.0-RC5) : " Error: Failed to synchronize cache for repo 'qubes-vm-r4.0-current' " #3737
qubesos-bot
added
r3.2-buster-stable
r3.2-jessie-stable
and removed
r3.2-buster-cur-test
r3.2-jessie-cur-test
labels
Apr 18, 2018
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
qubesos-bot
Apr 18, 2018
Automated announcement from builder-github
The package qubes-core-agent_3.2.28-1+deb9u1 has been pushed to the r3.2 stable repository for the Debian template.
To install this update, please use the standard update command:
sudo apt-get update && sudo apt-get dist-upgrade
qubesos-bot
commented
Apr 18, 2018
|
Automated announcement from builder-github The package |
qubesos-bot
added
r3.2-stretch-stable
r3.2-fc25-stable
and removed
r3.2-stretch-cur-test
r3.2-fc25-cur-test
labels
Apr 18, 2018
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
qubesos-bot
Apr 18, 2018
Automated announcement from builder-github
The component core-agent-linux (including package python2-dnf-plugins-qubes-hooks-3.2.28-1.fc26) has been pushed to the r3.2 stable repository for the Fedora template.
To install this update, please use the standard update command:
sudo yum update
qubesos-bot
commented
Apr 18, 2018
|
Automated announcement from builder-github The component |
vincentadultman commentedSep 29, 2017
Qubes OS version:
R3.2
Affected TemplateVMs (e.g.,
fedora-23, if applicable):Fedora-25-minimal
Steps to reproduce the behavior / Actual behavior:
Boot system, updates of templates operate normally. Suspend system, resume. Updates of templates fail with messages like "Error: Failed to synchronize cache for repo 'updates'. Issues is reproducible following every suspend / resume/
In sys-net running systemctl status qubes-updates-proxy yields
● qubes-updates-proxy.service - Qubes updates proxy (tinyproxy)
Loaded: loaded (/usr/lib/systemd/system/qubes-updates-proxy.service; enabled; vendor preset: enabled)
Active: failed (Result: start-limit-hit) since Fri 2017-09-29 17:12:26 BST; 2min 35s ago
Process: 13109 ExecStopPost=/usr/lib/qubes/iptables-updates-proxy stop (code=exited, status=0/SUCCESS)
Process: 13088 ExecStart=/usr/sbin/tinyproxy -d -c /etc/tinyproxy/tinyproxy-updates.conf (code=exited, status=0/SUCCESS)
Process: 13080 ExecStartPre=/usr/lib/qubes/iptables-updates-proxy start (code=exited, status=0/SUCCESS)
Main PID: 13088 (code=exited, status=0/SUCCESS)
Issuing systemctl restart qubes-updates-proxy resolves the issue.
Expected behavior:
Templates are updated without having to manually restart the proxy following suspend / resume.
General notes:
Others may be having similar issues, see https://groups.google.com/forum/#!msg/qubes-users/zldmwTEy51A/YCyH9X2eAgAJ