v4.1.0 TP in section bandwidth shows unrealistic values

[cheluskin]

I'm submitting a ...

• [X] bug report
• [ ] new feature / enhancement request
• [ ] improvement request (usability, performance, tech debt, etc.)
• [ ] other

Traffic Control components affected ...

• [ ] CDN in a Box
• [ ] Documentation
• [ ] Grove
• [ ] Traffic Control Client
• [X] Traffic Monitor
• [ ] Traffic Ops
• [ ] Traffic Ops ORT
• [X] Traffic Portal
• [ ] Traffic Router
• [ ] Traffic Stats
• [ ] Traffic Vault
• [ ] unknown

Current behavior:

(v4.1.0) TP in section bandwidth shows unrealistic values. Perhaps because: "Cache 'par1' has 2 interfaces, we have arbitrarily chosen lo for vitality"? At the same time, I have the eth0 interface specified for the edge cache. But he still chooses lo through time.

Expected / new behavior:

Bandwidth shown in TP should be accurate.

Minimal reproduction of the problem with instructions:

Set health.polling.format to stats_over_http

Anything else:

stats data

{
	"plugin.system_stats.loadavg.one": "2528",
	"plugin.system_stats.loadavg.five": "2464",
	"plugin.system_stats.loadavg.fifteen": "3136",
	"plugin.system_stats.current_processes": "126",
	"plugin.system_stats.net.lo.collisions": "0",
	"plugin.system_stats.net.lo.multicast": "0",
	"plugin.system_stats.net.lo.rx_bytes": "2592",
	"plugin.system_stats.net.lo.rx_compressed": "0",
	"plugin.system_stats.net.lo.rx_crc_errors": "0",
	"plugin.system_stats.net.lo.rx_dropped": "0",
	"plugin.system_stats.net.lo.rx_errors": "0",
	"plugin.system_stats.net.lo.rx_fifo_errors": "0",
	"plugin.system_stats.net.lo.rx_frame_errors": "0",
	"plugin.system_stats.net.lo.rx_length_errors": "0",
	"plugin.system_stats.net.lo.rx_missed_errors": "0",
	"plugin.system_stats.net.lo.rx_nohandler": "0",
	"plugin.system_stats.net.lo.rx_over_errors": "0",
	"plugin.system_stats.net.lo.rx_packets": "32",
	"plugin.system_stats.net.lo.tx_aborted_errors": "0",
	"plugin.system_stats.net.lo.tx_bytes": "2592",
	"plugin.system_stats.net.lo.tx_carrier_errors": "0",
	"plugin.system_stats.net.lo.tx_compressed": "0",
	"plugin.system_stats.net.lo.tx_dropped": "0",
	"plugin.system_stats.net.lo.tx_errors": "0",
	"plugin.system_stats.net.lo.tx_fifo_errors": "0",
	"plugin.system_stats.net.lo.tx_heartbeat_errors": "0",
	"plugin.system_stats.net.lo.tx_packets": "32",
	"plugin.system_stats.net.lo.tx_window_errors": "0",
	"plugin.system_stats.net.eth0.speed": "2500",
	"plugin.system_stats.net.eth0.collisions": "0",
	"plugin.system_stats.net.eth0.multicast": "150",
	"plugin.system_stats.net.eth0.rx_bytes": "47975405",
	"plugin.system_stats.net.eth0.rx_compressed": "0",
	"plugin.system_stats.net.eth0.rx_crc_errors": "0",
	"plugin.system_stats.net.eth0.rx_dropped": "0",
	"plugin.system_stats.net.eth0.rx_errors": "0",
	"plugin.system_stats.net.eth0.rx_fifo_errors": "0",
	"plugin.system_stats.net.eth0.rx_frame_errors": "0",
	"plugin.system_stats.net.eth0.rx_length_errors": "0",
	"plugin.system_stats.net.eth0.rx_missed_errors": "0",
	"plugin.system_stats.net.eth0.rx_nohandler": "0",
	"plugin.system_stats.net.eth0.rx_over_errors": "0",
	"plugin.system_stats.net.eth0.rx_packets": "566274",
	"plugin.system_stats.net.eth0.tx_aborted_errors": "0",
	"plugin.system_stats.net.eth0.tx_bytes": "563266623",
	"plugin.system_stats.net.eth0.tx_carrier_errors": "0",
	"plugin.system_stats.net.eth0.tx_compressed": "0",
	"plugin.system_stats.net.eth0.tx_dropped": "0",
	"plugin.system_stats.net.eth0.tx_errors": "0",
	"plugin.system_stats.net.eth0.tx_fifo_errors": "0",
	"plugin.system_stats.net.eth0.tx_heartbeat_errors": "0",
	"plugin.system_stats.net.eth0.tx_packets": "533070",
	"plugin.system_stats.net.eth0.tx_window_errors": "0"
}

Traffic Monitor Logs

INFO: cache.go:50: 2020-07-23T08:19:58.193827603+02:00: Cache 'par1' has 2 interfaces, we have arbitrarily chosen lo for vitality
DEBUG: health.go:157: 2020-07-23T08:19:58.193951339+02:00: poll 483 2020-07-23 08:19:58.19395053 +0200 CEST m=+1877.444887335 finish
INFO: cachestate.go:160: 2020-07-23T08:19:59.852378548+02:00: cache not in connections par1
INFO: cachestate.go:160: 2020-07-23T08:20:00.419158688+02:00: cache not in connections par1
INFO: cachestate.go:160: 2020-07-23T08:20:01.668051484+02:00: cache not in connections par1
DEBUG: cache.go:177: 2020-07-23T08:20:04.000124122+02:00: Intended Duration: 2.91s Actual Duration: 5.819796034s
DEBUG: cache.go:183: 2020-07-23T08:20:04.000220995+02:00: poll 484 2020-07-23 08:20:04.000218892 +0200 CEST m=+1883.251155687 start
DEBUG: cache.go:195: 2020-07-23T08:20:04.012208773+02:00: poll 484 2020-07-23 08:20:04.012207052 +0200 CEST m=+1883.263143853 poller end
DEBUG: cache.go:266: 2020-07-23T08:20:04.012329722+02:00: poll 484 2020-07-23 08:20:04.012327373 +0200 CEST m=+1883.263264221 (format 'stats_over_http') handle start
INFO: cache.go:50: 2020-07-23T08:20:04.013666204+02:00: Cache 'par1' has 2 interfaces, we have arbitrarily chosen lo for vitality
DEBUG: health.go:157: 2020-07-23T08:20:04.013789856+02:00: poll 484 2020-07-23 08:20:04.013789068 +0200 CEST m=+1883.264725872 finish
INFO: cachestate.go:160: 2020-07-23T08:20:04.862111995+02:00: cache not in connections par1
INFO: cachestate.go:160: 2020-07-23T08:20:05.429508687+02:00: cache not in connections par1
INFO: cachestate.go:160: 2020-07-23T08:20:06.676413071+02:00: cache not in connections par1
DEBUG: cache.go:177: 2020-07-23T08:20:09.504103124+02:00: Intended Duration: 5.82s Actual Duration: 11.639834072s
DEBUG: cache.go:183: 2020-07-23T08:20:09.504254331+02:00: poll 485 2020-07-23 08:20:09.504251727 +0200 CEST m=+1888.755188561 start
DEBUG: cache.go:195: 2020-07-23T08:20:09.516261211+02:00: poll 485 2020-07-23 08:20:09.516259426 +0200 CEST m=+1888.767196231 poller end
DEBUG: cache.go:266: 2020-07-23T08:20:09.516351639+02:00: poll 485 2020-07-23 08:20:09.516349755 +0200 CEST m=+1888.767286559 (format 'stats_over_http') handle start
INFO: stat.go:165: 2020-07-23T08:20:09.517811369+02:00: StatHistoryManager starting flushLoop with 1 results
INFO: stat.go:181: 2020-07-23T08:20:09.517848963+02:00: StatHistoryManager flushLoop: stat chan is empty, processing 1 results
INFO: cache.go:50: 2020-07-23T08:20:09.518129931+02:00: Cache 'par1' has 2 interfaces, we have arbitrarily chosen lo for vitality
INFO: monitorconfig.go:269: 2020-07-23T08:20:09.518272784+02:00: health.polling.type for 'par1' is empty, using default 'http'
INFO: stat.go:458: 2020-07-23T08:20:09.519572488+02:00: CreateStats took 23.866µs
INFO: stat.go:200: 2020-07-23T08:20:09.519758039+02:00: StatHistoryManager bufferLoop exiting flush loop, resetting buffer timer
DEBUG: cache.go:177: 2020-07-23T08:20:09.820189961+02:00: Intended Duration: 2.91s Actual Duration: 5.819969386s
DEBUG: cache.go:183: 2020-07-23T08:20:09.820316121+02:00: poll 486 2020-07-23 08:20:09.820313753 +0200 CEST m=+1889.071250550 start
DEBUG: cache.go:195: 2020-07-23T08:20:09.832259182+02:00: poll 486 2020-07-23 08:20:09.832257041 +0200 CEST m=+1889.083193875 poller end
DEBUG: cache.go:266: 2020-07-23T08:20:09.832380148+02:00: poll 486 2020-07-23 08:20:09.832377248 +0200 CEST m=+1889.083314076 (format 'stats_over_http') handle start
INFO: cache.go:50: 2020-07-23T08:20:09.833856275+02:00: Cache 'par1' has 2 interfaces, we have arbitrarily chosen eth0 for vitality
DEBUG: health.go:157: 2020-07-23T08:20:09.834013038+02:00: poll 486 2020-07-23 08:20:09.834012303 +0200 CEST m=+1889.084949107 finish
INFO: cachestate.go:160: 2020-07-23T08:20:09.872191201+02:00: cache not in connections par1
INFO: cachestate.go:160: 2020-07-23T08:20:10.440866399+02:00: cache not in connections par1
INFO: cachestate.go:160: 2020-07-23T08:20:11.685387179+02:00: cache not in connections par1
INFO: cachestate.go:160: 2020-07-23T08:20:14.879488774+02:00: cache not in connections par1
INFO: cachestate.go:160: 2020-07-23T08:20:15.446891369+02:00: cache not in connections par1
DEBUG: cache.go:177: 2020-07-23T08:20:15.640177985+02:00: Intended Duration: 2.91s Actual Duration: 5.819871162s
DEBUG: cache.go:183: 2020-07-23T08:20:15.640277274+02:00: poll 487 2020-07-23 08:20:15.640275373 +0200 CEST m=+1894.891212181 start
DEBUG: cache.go:195: 2020-07-23T08:20:15.652944493+02:00: poll 487 2020-07-23 08:20:15.652942886 +0200 CEST m=+1894.903879751 poller end
DEBUG: cache.go:266: 2020-07-23T08:20:15.653071918+02:00: poll 487 2020-07-23 08:20:15.653069776 +0200 CEST m=+1894.904006611 (format 'stats_over_http') handle start
INFO: cache.go:50: 2020-07-23T08:20:15.654448087+02:00: Cache 'par1' has 2 interfaces, we have arbitrarily chosen lo for vitality
DEBUG: health.go:157: 2020-07-23T08:20:15.654584696+02:00: poll 487 2020-07-23 08:20:15.654583858 +0200 CEST m=+1894.905520662 finish
INFO: cachestate.go:160: 2020-07-23T08:20:16.700575705+02:00: cache not in connections par1
INFO: cachestate.go:160: 2020-07-23T08:20:19.890302442+02:00: cache not in connections par1
INFO: cachestate.go:160: 2020-07-23T08:20:20.457305306+02:00: cache not in connections par1
DEBUG: cache.go:177: 2020-07-23T08:20:21.144148315+02:00: Intended Duration: 5.82s Actual Duration: 11.639893516s
DEBUG: cache.go:183: 2020-07-23T08:20:21.144224398+02:00: poll 488 2020-07-23 08:20:21.144221869 +0200 CEST m=+1900.395158673 start
DEBUG: cache.go:195: 2020-07-23T08:20:21.156241422+02:00: poll 488 2020-07-23 08:20:21.156240116 +0200 CEST m=+1900.407176917 poller end
DEBUG: cache.go:266: 2020-07-23T08:20:21.156334267+02:00: poll 488 2020-07-23 08:20:21.156332032 +0200 CEST m=+1900.407268907 (format 'stats_over_http') handle start
INFO: stat.go:165: 2020-07-23T08:20:21.157818723+02:00: StatHistoryManager starting flushLoop with 1 results
INFO: stat.go:181: 2020-07-23T08:20:21.157869885+02:00: StatHistoryManager flushLoop: stat chan is empty, processing 1 results
INFO: cache.go:50: 2020-07-23T08:20:21.157952913+02:00: Cache 'par1' has 2 interfaces, we have arbitrarily chosen lo for vitality

[cheluskin]

[zrhoffman]

What Traffic Control version are you using?

[cheluskin]

4.1.0 version

[mitchell852]

@cheluskin unfortunately 4.x is no longer supported. can you upgrade to a currently supported version and see if you still have the problem? https://github.com/apache/trafficcontrol/security/policy