Probe executes out of schedule when configuration is read from dump
Problem description
When the agent reads the configuration from the dump file, it executes the probes instantly, without consideration for the actual probe configuration's schedule.
In this example, the agent is run. In normal mode, the probe is fired every minute. Then the server is shutdown, and the probe is fired around every 3 seconds. When the server is available again, the agent resumes its regular schedule.
Normal operation:
16:56:05.202 [DEBU] func1: Timer for probe ping fired at 2018-12-27 16:56:05.202001 +0100 CET m=+293.422549594 (scheduler.go:216)
16:57:05.202 [DEBU] func1: Timer for probe ping fired at 2018-12-27 16:57:05.202548 +0100 CET m=+353.424331552 (scheduler.go:216)
16:58:05.196 [DEBU] func1: Timer for probe ping fired at 2018-12-27 16:58:05.196457 +0100 CET m=+413.419474515 (scheduler.go:216)
16:59:05.197 [DEBU] func1: Timer for probe ping fired at 2018-12-27 16:59:05.197065 +0100 CET m=+473.421316862 (scheduler.go:216)
Server shutdown:
17:00:05.194 [DEBU] func1: Timer for probe ping fired at 2018-12-27 17:00:05.194194 +0100 CET m=+533.419680262 (scheduler.go:216)
17:00:08.330 [ERRO] run: could not send results: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp [::1]:7575: connect: connection refused" (main.go:301)
17:00:08.330 [INFO] run: Panto server could not be reached, spooling 1 results (main.go:306)
17:00:08.330 [WARN] dump: Can't dump spooler to file: no path specified (spooler.go:128)
17:00:08.330 [ERRO] RequestConfiguration: could not receive configuration: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp [::1]:7575: connect: connection refused" (client.go:234)
17:00:08.330 [INFO] localConfigurationLoad: trying to load configuration from dump: /Users/chrales/.panto/agent-config.dump (client.go:294)
17:00:08.332 [INFO] RequestConfiguration: Received configuration version 1545923859000000000 with 1 Probe Configuration(s) (client.go:247)
17:00:08.333 [DEBU] RequestConfiguration: Configuration dumped on disk: /Users/chrales/.panto/agent-config.dump (client.go:252)
17:00:08.333 [DEBU] ConfigureScheduler: Probe configuration 0: &api.ProbeConfiguration{Name:"organizations/cZhUTZTkTkq9dc3TuGc8Gg/agents/_-JTsCdIR7eLDm7jKrrrEQ/probeconfigurations/tnL-lSudSPqeDGb2G2rF-A", Check:"organizations/cZhUTZTkTkq9dc3TuGc8Gg/checks/1mnu85cFSVWFl7NMjEguIQ", Configuration:"{\"address\":\"8.8.8.8\"}", ProbeLabel:"ping", Schedule:(*duration.Duration)(0xc0003ff230), Target:(*api.Target)(nil), XXX_NoUnkeyedLiteral:struct {}{}, XXX_unrecognized:[]uint8(nil), XXX_sizecache:212} (scheduler.go:292)
17:00:08.333 [DEBU] AddProbe: Timer for probe ping fired at 2018-12-27 17:00:08.333548 +0100 CET m=+536.559099298 (scheduler.go:204)
17:00:11.462 [ERRO] run: could not send results: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp [::1]:7575: connect: connection refused" (main.go:301)
17:00:11.462 [INFO] run: Panto server could not be reached, spooling 1 results (main.go:306)
17:00:11.462 [WARN] dump: Can't dump spooler to file: no path specified (spooler.go:128)
17:00:11.462 [ERRO] RequestConfiguration: could not receive configuration: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp [::1]:7575: connect: connection refused" (client.go:234)
17:00:11.462 [INFO] localConfigurationLoad: trying to load configuration from dump: /Users/chrales/.panto/agent-config.dump (client.go:294)
17:00:11.462 [INFO] RequestConfiguration: Received configuration version 1545923859000000000 with 1 Probe Configuration(s) (client.go:247)
17:00:11.463 [DEBU] RequestConfiguration: Configuration dumped on disk: /Users/chrales/.panto/agent-config.dump (client.go:252)
17:00:11.463 [DEBU] ConfigureScheduler: Probe configuration 0: &api.ProbeConfiguration{Name:"organizations/cZhUTZTkTkq9dc3TuGc8Gg/agents/_-JTsCdIR7eLDm7jKrrrEQ/probeconfigurations/tnL-lSudSPqeDGb2G2rF-A", Check:"organizations/cZhUTZTkTkq9dc3TuGc8Gg/checks/1mnu85cFSVWFl7NMjEguIQ", Configuration:"{\"address\":\"8.8.8.8\"}", ProbeLabel:"ping", Schedule:(*duration.Duration)(0xc000173200), Target:(*api.Target)(nil), XXX_NoUnkeyedLiteral:struct {}{}, XXX_unrecognized:[]uint8(nil), XXX_sizecache:212} (scheduler.go:292)
17:00:11.463 [DEBU] AddProbe: Timer for probe ping fired at 2018-12-27 17:00:11.463267 +0100 CET m=+539.688882027 (scheduler.go:204)
17:00:14.591 [ERRO] run: could not send results: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp [::1]:7575: connect: connection refused" (main.go:301)
17:00:14.591 [INFO] run: Panto server could not be reached, spooling 1 results (main.go:306)
17:00:14.591 [WARN] dump: Can't dump spooler to file: no path specified (spooler.go:128)
17:00:14.591 [ERRO] RequestConfiguration: could not receive configuration: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp [::1]:7575: connect: connection refused" (client.go:234)
17:00:14.591 [INFO] localConfigurationLoad: trying to load configuration from dump: /Users/chrales/.panto/agent-config.dump (client.go:294)
17:00:14.591 [INFO] RequestConfiguration: Received configuration version 1545923859000000000 with 1 Probe Configuration(s) (client.go:247)
17:00:14.592 [DEBU] RequestConfiguration: Configuration dumped on disk: /Users/chrales/.panto/agent-config.dump (client.go:252)
17:00:14.592 [DEBU] ConfigureScheduler: Probe configuration 0: &api.ProbeConfiguration{Name:"organizations/cZhUTZTkTkq9dc3TuGc8Gg/agents/_-JTsCdIR7eLDm7jKrrrEQ/probeconfigurations/tnL-lSudSPqeDGb2G2rF-A", Check:"organizations/cZhUTZTkTkq9dc3TuGc8Gg/checks/1mnu85cFSVWFl7NMjEguIQ", Configuration:"{\"address\":\"8.8.8.8\"}", ProbeLabel:"ping", Schedule:(*duration.Duration)(0xc0000b7ce0), Target:(*api.Target)(nil), XXX_NoUnkeyedLiteral:struct {}{}, XXX_unrecognized:[]uint8(nil), XXX_sizecache:212} (scheduler.go:292)
17:00:14.592 [DEBU] AddProbe: Timer for probe ping fired at 2018-12-27 17:00:14.592261 +0100 CET m=+542.817941208 (scheduler.go:204)
17:00:17.744 [ERRO] run: could not send results: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp [::1]:7575: connect: connection refused" (main.go:301)
17:00:17.744 [INFO] run: Panto server could not be reached, spooling 1 results (main.go:306)
17:00:17.745 [WARN] dump: Can't dump spooler to file: no path specified (spooler.go:128)
17:00:17.745 [ERRO] RequestConfiguration: could not receive configuration: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp [::1]:7575: connect: connection refused" (client.go:234)
17:00:17.745 [INFO] localConfigurationLoad: trying to load configuration from dump: /Users/chrales/.panto/agent-config.dump (client.go:294)
17:00:17.745 [INFO] RequestConfiguration: Received configuration version 1545923859000000000 with 1 Probe Configuration(s) (client.go:247)
17:00:17.745 [DEBU] RequestConfiguration: Configuration dumped on disk: /Users/chrales/.panto/agent-config.dump (client.go:252)
17:00:17.745 [DEBU] ConfigureScheduler: Probe configuration 0: &api.ProbeConfiguration{Name:"organizations/cZhUTZTkTkq9dc3TuGc8Gg/agents/_-JTsCdIR7eLDm7jKrrrEQ/probeconfigurations/tnL-lSudSPqeDGb2G2rF-A", Check:"organizations/cZhUTZTkTkq9dc3TuGc8Gg/checks/1mnu85cFSVWFl7NMjEguIQ", Configuration:"{\"address\":\"8.8.8.8\"}", ProbeLabel:"ping", Schedule:(*duration.Duration)(0xc000173e60), Target:(*api.Target)(nil), XXX_NoUnkeyedLiteral:struct {}{}, XXX_unrecognized:[]uint8(nil), XXX_sizecache:212} (scheduler.go:292)
17:00:17.745 [DEBU] AddProbe: Timer for probe ping fired at 2018-12-27 17:00:17.745865 +0100 CET m=+545.971609529 (scheduler.go:204)
17:00:20.870 [ERRO] run: could not send results: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp [::1]:7575: connect: connection refused" (main.go:301)
17:00:20.870 [INFO] run: Panto server could not be reached, spooling 1 results (main.go:306)
17:00:20.870 [WARN] dump: Can't dump spooler to file: no path specified (spooler.go:128)
17:00:20.870 [ERRO] RequestConfiguration: could not receive configuration: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp [::1]:7575: connect: connection refused" (client.go:234)
17:00:20.870 [INFO] localConfigurationLoad: trying to load configuration from dump: /Users/chrales/.panto/agent-config.dump (client.go:294)
17:00:20.871 [INFO] RequestConfiguration: Received configuration version 1545923859000000000 with 1 Probe Configuration(s) (client.go:247)
17:00:20.871 [DEBU] RequestConfiguration: Configuration dumped on disk: /Users/chrales/.panto/agent-config.dump (client.go:252)
17:00:20.871 [DEBU] ConfigureScheduler: Probe configuration 0: &api.ProbeConfiguration{Name:"organizations/cZhUTZTkTkq9dc3TuGc8Gg/agents/_-JTsCdIR7eLDm7jKrrrEQ/probeconfigurations/tnL-lSudSPqeDGb2G2rF-A", Check:"organizations/cZhUTZTkTkq9dc3TuGc8Gg/checks/1mnu85cFSVWFl7NMjEguIQ", Configuration:"{\"address\":\"8.8.8.8\"}", ProbeLabel:"ping", Schedule:(*duration.Duration)(0xc000256720), Target:(*api.Target)(nil), XXX_NoUnkeyedLiteral:struct {}{}, XXX_unrecognized:[]uint8(nil), XXX_sizecache:212} (scheduler.go:292)
17:00:20.871 [DEBU] AddProbe: Timer for probe ping fired at 2018-12-27 17:00:20.871678 +0100 CET m=+549.097487037 (scheduler.go:204)
17:00:24.001 [ERRO] run: could not send results: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp [::1]:7575: connect: connection refused" (main.go:301)
17:00:24.001 [INFO] run: Panto server could not be reached, spooling 1 results (main.go:306)
17:00:24.001 [WARN] dump: Can't dump spooler to file: no path specified (spooler.go:128)
17:00:24.001 [ERRO] RequestConfiguration: could not receive configuration: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp [::1]:7575: connect: connection refused" (client.go:234)
17:00:24.001 [INFO] localConfigurationLoad: trying to load configuration from dump: /Users/chrales/.panto/agent-config.dump (client.go:294)
17:00:24.001 [INFO] RequestConfiguration: Received configuration version 1545923859000000000 with 1 Probe Configuration(s) (client.go:247)
17:00:24.002 [DEBU] RequestConfiguration: Configuration dumped on disk: /Users/chrales/.panto/agent-config.dump (client.go:252)
17:00:24.002 [DEBU] ConfigureScheduler: Probe configuration 0: &api.ProbeConfiguration{Name:"organizations/cZhUTZTkTkq9dc3TuGc8Gg/agents/_-JTsCdIR7eLDm7jKrrrEQ/probeconfigurations/tnL-lSudSPqeDGb2G2rF-A", Check:"organizations/cZhUTZTkTkq9dc3TuGc8Gg/checks/1mnu85cFSVWFl7NMjEguIQ", Configuration:"{\"address\":\"8.8.8.8\"}", ProbeLabel:"ping", Schedule:(*duration.Duration)(0xc00026a3f0), Target:(*api.Target)(nil), XXX_NoUnkeyedLiteral:struct {}{}, XXX_unrecognized:[]uint8(nil), XXX_sizecache:212} (scheduler.go:292)
Server startup
17:00:24.002 [DEBU] AddProbe: Timer for probe ping fired at 2018-12-27 17:00:24.002542 +0100 CET m=+552.228415264 (scheduler.go:204)
17:00:27.141 [INFO] run: sent 6 spooled results (main.go:323)
17:00:27.141 [WARN] dump: Can't dump spooler to file: no path specified (spooler.go:128)
17:01:24.004 [DEBU] func1: Timer for probe ping fired at 2018-12-27 17:01:24.004081 +0100 CET m=+612.231189503 (scheduler.go:216)
17:02:24.002 [DEBU] func1: Timer for probe ping fired at 2018-12-27 17:02:24.002311 +0100 CET m=+672.230653599 (scheduler.go:216)
17:03:24.002 [DEBU] func1: Timer for probe ping fired at 2018-12-27 17:03:24.002445 +0100 CET m=+732.232022025 (scheduler.go:216)
17:04:23.999 [DEBU] func1: Timer for probe ping fired at 2018-12-27 17:04:23.999182 +0100 CET m=+792.229993588 (scheduler.go:216)
Environment
Panto versions
- Panto server version:
0.5.0-8cccf548
- Panto agent version:
0.5.0-8cccf548
- Panto web version:
0.5.0-8cccf548
Local environment
- Operating system: macOS High Sierra 10.13.6
- Browser and version: Google Chrome Version 71.0.3578.98 (Official Build) (64-bit)
Reproduction
- Run the server
- Make sure there is an agent with a probe configuration on it
- Run the agent with a configuration dump location
- Wait until the agent has fired a probe a few times
- Shutdown the server
Expected behavior
The agent reads the probe configurations from the dump file and spools the results at the same schedule.
Observed behavior
The agent reads the probe configurations from the dump file, spools the results, re-reads the dump file, and re-runs the probes.