Enhance documentation and error reporting

[HiranChaudhuri]

Hi there.

I am trying to run the docker image but it seems to fail. The error message does not really indicate what I could fix. It's a new setup so it never worked before...

docker run --net=host -p9133:9133 mxschmitt/fritzbox_exporter -stdout
WARNING: Published ports are discarded when using host network mode
2019/12/09 21:15:53 could not print metrics to stdout: could not load UPnP service: could not load Tr64: could not decode XML: XML syntax error on line 1: element <HR> closed by </BODY>

If I try to access the metrics I get this:

curl http://localhost:9133
404 page not found

All this is run against a Fritzbox 7490 that has metrics exposed via UPNP.

curl http://fritz.box:49000/igddesc.xml
<?xml version="1.0"?>
<root xmlns="urn:schemas-upnp-org:device-1-0">
<specVersion>
<major>1</major>
<minor>0</minor>
</specVersion>
<device>
<deviceType>urn:schemas-upnp-org:device:InternetGatewayDevice:1</deviceType>
<friendlyName>Gateway</friendlyName>
<manufacturer>AVM Berlin</manufacturer>
...

[mxschmitt]

Metrics are exposed on the /metrics endpoint like described here: https://github.com/mxschmitt/fritzbox_exporter#with-docker

[HiranChaudhuri]

Good point - all those exporters send to /metrics. So I rephrase my request and the result looks better but not perfect. I can now see metrics related to the Go language so I'd say the exporter itself but nothing related to my fritz box or data connection. Is the error from the docker container related?

curl http://localhost:9133/metrics
# HELP fritzbox_exporter_collect_errors Number of collection errors.
# TYPE fritzbox_exporter_collect_errors counter
fritzbox_exporter_collect_errors 0
# HELP go_gc_duration_seconds A summary of the GC invocation durations.
# TYPE go_gc_duration_seconds summary
go_gc_duration_seconds{quantile="0"} 5.2776e-05
go_gc_duration_seconds{quantile="0.25"} 0.000119128
go_gc_duration_seconds{quantile="0.5"} 0.000149854
go_gc_duration_seconds{quantile="0.75"} 0.000284369
go_gc_duration_seconds{quantile="1"} 0.004945139
go_gc_duration_seconds_sum 0.057881786
go_gc_duration_seconds_count 250
# HELP go_goroutines Number of goroutines that currently exist.
# TYPE go_goroutines gauge
go_goroutines 10
# HELP go_info Information about the Go environment.
# TYPE go_info gauge
go_info{version="go1.12.6"} 1
# HELP go_memstats_alloc_bytes Number of bytes allocated and still in use.
# TYPE go_memstats_alloc_bytes gauge
go_memstats_alloc_bytes 3.250376e+06
# HELP go_memstats_alloc_bytes_total Total number of bytes allocated, even if freed.
# TYPE go_memstats_alloc_bytes_total counter
go_memstats_alloc_bytes_total 8.18344568e+08
# HELP go_memstats_buck_hash_sys_bytes Number of bytes used by the profiling bucket hash table.
# TYPE go_memstats_buck_hash_sys_bytes gauge
go_memstats_buck_hash_sys_bytes 1.496015e+06
# HELP go_memstats_frees_total Total number of frees.
# TYPE go_memstats_frees_total counter
go_memstats_frees_total 3.904743e+06
# HELP go_memstats_gc_cpu_fraction The fraction of this program's available CPU time used by the GC since the program started.
# TYPE go_memstats_gc_cpu_fraction gauge
go_memstats_gc_cpu_fraction 2.1160863701151764e-05
# HELP go_memstats_gc_sys_bytes Number of bytes used for garbage collection system metadata.
# TYPE go_memstats_gc_sys_bytes gauge
go_memstats_gc_sys_bytes 2.377728e+06
# HELP go_memstats_heap_alloc_bytes Number of heap bytes allocated and still in use.
# TYPE go_memstats_heap_alloc_bytes gauge
go_memstats_heap_alloc_bytes 3.250376e+06
# HELP go_memstats_heap_idle_bytes Number of heap bytes waiting to be used.
# TYPE go_memstats_heap_idle_bytes gauge
go_memstats_heap_idle_bytes 6.2103552e+07
# HELP go_memstats_heap_inuse_bytes Number of heap bytes that are in use.
# TYPE go_memstats_heap_inuse_bytes gauge
go_memstats_heap_inuse_bytes 4.21888e+06
# HELP go_memstats_heap_objects Number of allocated objects.
# TYPE go_memstats_heap_objects gauge
go_memstats_heap_objects 15579
# HELP go_memstats_heap_released_bytes Number of heap bytes released to OS.
# TYPE go_memstats_heap_released_bytes gauge
go_memstats_heap_released_bytes 0
# HELP go_memstats_heap_sys_bytes Number of heap bytes obtained from system.
# TYPE go_memstats_heap_sys_bytes gauge
go_memstats_heap_sys_bytes 6.6322432e+07
# HELP go_memstats_last_gc_time_seconds Number of seconds since 1970 of last garbage collection.
# TYPE go_memstats_last_gc_time_seconds gauge
go_memstats_last_gc_time_seconds 1.5759945120680084e+09
# HELP go_memstats_lookups_total Total number of pointer lookups.
# TYPE go_memstats_lookups_total counter
go_memstats_lookups_total 0
# HELP go_memstats_mallocs_total Total number of mallocs.
# TYPE go_memstats_mallocs_total counter
go_memstats_mallocs_total 3.920322e+06
# HELP go_memstats_mcache_inuse_bytes Number of bytes in use by mcache structures.
# TYPE go_memstats_mcache_inuse_bytes gauge
go_memstats_mcache_inuse_bytes 6944
# HELP go_memstats_mcache_sys_bytes Number of bytes used for mcache structures obtained from system.
# TYPE go_memstats_mcache_sys_bytes gauge
go_memstats_mcache_sys_bytes 16384
# HELP go_memstats_mspan_inuse_bytes Number of bytes in use by mspan structures.
# TYPE go_memstats_mspan_inuse_bytes gauge
go_memstats_mspan_inuse_bytes 40464
# HELP go_memstats_mspan_sys_bytes Number of bytes used for mspan structures obtained from system.
# TYPE go_memstats_mspan_sys_bytes gauge
go_memstats_mspan_sys_bytes 65536
# HELP go_memstats_next_gc_bytes Number of heap bytes when next garbage collection will take place.
# TYPE go_memstats_next_gc_bytes gauge
go_memstats_next_gc_bytes 4.194304e+06
# HELP go_memstats_other_sys_bytes Number of bytes used for other system allocations.
# TYPE go_memstats_other_sys_bytes gauge
go_memstats_other_sys_bytes 1.221929e+06
# HELP go_memstats_stack_inuse_bytes Number of bytes in use by the stack allocator.
# TYPE go_memstats_stack_inuse_bytes gauge
go_memstats_stack_inuse_bytes 786432
# HELP go_memstats_stack_sys_bytes Number of bytes obtained from system for stack allocator.
# TYPE go_memstats_stack_sys_bytes gauge
go_memstats_stack_sys_bytes 786432
# HELP go_memstats_sys_bytes Number of bytes obtained from system.
# TYPE go_memstats_sys_bytes gauge
go_memstats_sys_bytes 7.2286456e+07
# HELP go_threads Number of OS threads created.
# TYPE go_threads gauge
go_threads 11
# HELP process_cpu_seconds_total Total user and system CPU time spent in seconds.
# TYPE process_cpu_seconds_total counter
process_cpu_seconds_total 37.36
# HELP process_max_fds Maximum number of open file descriptors.
# TYPE process_max_fds gauge
process_max_fds 1.048576e+06
# HELP process_open_fds Number of open file descriptors.
# TYPE process_open_fds gauge
process_open_fds 9
# HELP process_resident_memory_bytes Resident memory size in bytes.
# TYPE process_resident_memory_bytes gauge
process_resident_memory_bytes 1.9185664e+07
# HELP process_start_time_seconds Start time of the process since unix epoch in seconds.
# TYPE process_start_time_seconds gauge
process_start_time_seconds 1.57597950856e+09
# HELP process_virtual_memory_bytes Virtual memory size in bytes.
# TYPE process_virtual_memory_bytes gauge
process_virtual_memory_bytes 1.14917376e+08
# HELP process_virtual_memory_max_bytes Maximum amount of virtual memory available in bytes.
# TYPE process_virtual_memory_max_bytes gauge
process_virtual_memory_max_bytes -1
# HELP promhttp_metric_handler_requests_in_flight Current number of scrapes being served.
# TYPE promhttp_metric_handler_requests_in_flight gauge
promhttp_metric_handler_requests_in_flight 1
# HELP promhttp_metric_handler_requests_total Total number of scrapes by HTTP status code.
# TYPE promhttp_metric_handler_requests_total counter
promhttp_metric_handler_requests_total{code="200"} 1003
promhttp_metric_handler_requests_total{code="500"} 0
promhttp_metric_handler_requests_total{code="503"} 0

[HiranChaudhuri]

Here the logs from my docker container:

docker logs fritzbox_arberweg
cannot load services: could not load Tr64: could not decode XML: XML syntax error on line 1: element <HR> closed by </BODY>
cannot load services: could not load Tr64: could not decode XML: XML syntax error on line 1: element <HR> closed by </BODY>
cannot load services: could not load Tr64: could not decode XML: XML syntax error on line 1: element <HR> closed by </BODY>
cannot load services: could not load Tr64: could not decode XML: XML syntax error on line 1: element <HR> closed by </BODY>
cannot load services: could not load Tr64: could not decode XML: XML syntax error on line 1: element <HR> closed by </BODY>
cannot load services: could not load Tr64: could not decode XML: XML syntax error on line 1: element <HR> closed by </BODY>
cannot load services: could not load Tr64: could not decode XML: XML syntax error on line 1: element <HR> closed by </BODY>
cannot load services: could not load Tr64: could not decode XML: XML syntax error on line 1: element <HR> closed by </BODY>
...

[HiranChaudhuri]

Seems connected to #8 although I have the FritzBox 7490 with OS 07.12.

[HiranChaudhuri]

From the error I assume the XML parser tries to read HTML content.

I suggest to extend the code at

fritzbox_exporter/pkg/fritzboxmetrics/fritzboxmetrics.go

Line 156 in b6069d2

return errors.Wrap(err, "could not decode XML")

by dumping URL and the response received. As the dump would just happen in case of errors that need to get fixed anyway the log size should not matter.

[HiranChaudhuri]

Looking closer at the source code I take it the exporter is trying to access http://fritz.box:49000/tr64desc.xml My Fritz Box responds to this URL with a 404 code:

<HTML><HEAD><TITLE>404 Not Found (ERR_NOT_FOUND)</TITLE></HEAD><BODY><H1>404 Not Found</H1><BR>ERR_NOT_FOUND<HR><B>Webserver</B> Tue, 10 Dec 2019 22:13:42 GMT</BODY></HTML>

This input could explain the error reported by the exporter.

Looking at https://www.schlaue-huette.de/apis-co/fritz-tr064/ it seems you have to activate both

• Zugriff für Anwendungen zulassen
• Statusinformationen über UPnP übertragen

Only the second one is active on my router as mentioned in https://github.com/mxschmitt/fritzbox_exporter#fritzos-700

[HiranChaudhuri]

I activated the first setting 'Zugriff für Anwendungen zulassen' and now the URL responds with an XML document. The exporter now reports authorization problems which is in sync with https://www.schlaue-huette.de/apis-co/fritz-tr064/

2019/12/10 22:27:50 could not call action: authorization required
2019/12/10 22:28:04 could not call action: authorization required
2019/12/10 22:28:19 could not call action: authorization required
2019/12/10 22:28:34 could not call action: authorization required
...

[HiranChaudhuri]

Confirmed. After creating a user and configuring that on the docker command line the metrics are available now.

BTW, the exporter binary accepts -user and -password parameters however the README.md does not list them.

All in all just some documentation update is required. Changes to the code could make detection easier.

[Zerwin]

@HiranChaudhuri Could you tell me how you configured the docker command line ? I currently am stuck on changing some of the parameters, using enviroment variables doesn't seem to work for me.

[HiranChaudhuri]

@HiranChaudhuri Could you tell me how you configured the docker command line ? I currently am stuck on changing some of the parameters, using enviroment variables doesn't seem to work for me.

You are struggling with the undocumented command line options - my docker command line contains this:
docker run mxschmitt/fritzbox_exporter -username youruser -password yourpassword
Mind to replace youruser and yourpassword with whatever you configure on your Fritzbox.