Tried to access X in _findUpstreamID() (/app/src/datastructure.c:155) but next_str_pos is Y

[schuettecarsten]

I can see lots of warnings like this on the console:

2024-11-05 10:52:59.609 CET [52M] WARNING: Tried to access 556484146445156980 in _findUpstreamID() (/app/src/datastructure.c:155) but next_str_pos is 103243
2024-11-05 10:52:59.609 CET [52M] WARNING: Tried to access 556487028368213333 in _findUpstreamID() (/app/src/datastructure.c:155) but next_str_pos is 103243
2024-11-05 10:52:59.609 CET [52M] WARNING: Tried to access 569986836429013639 in _findUpstreamID() (/app/src/datastructure.c:155) but next_str_pos is 103243
2024-11-05 10:52:59.609 CET [52M] WARNING: Tried to access 602646729820471976 in _findUpstreamID() (/app/src/datastructure.c:155) but next_str_pos is 103243
2024-11-05 10:52:59.609 CET [52M] WARNING: Tried to access 621222429015933616 in _findUpstreamID() (/app/src/datastructure.c:155) but next_str_pos is 103243
2024-11-05 10:52:59.609 CET [52M] WARNING: Tried to access 636985023416763080 in _findUpstreamID() (/app/src/datastructure.c:155) but next_str_pos is 103243
2024-11-05 10:52:59.610 CET [52M] WARNING: Tried to access 658653653116125990 in _findUpstreamID() (/app/src/datastructure.c:155) but next_str_pos is 103243
2024-11-05 10:52:59.610 CET [52M] WARNING: Tried to access 680898968074323662 in _findUpstreamID() (/app/src/datastructure.c:155) but next_str_pos is 103243
2024-11-05 10:52:59.610 CET [52M] WARNING: Tried to access 683991344527442757 in _findUpstreamID() (/app/src/datastructure.c:155) but next_str_pos is 103243

Versions:
Docker Tag nightly
Core vDev (development, 112b9617)
FTL vDev (development, 510cb1b)
Web interface vDev (development, c689fdc7)

[DL6ER]

Can you reproduce this? As in: Does it happen again (relatively soon) after restarting pihole-FTL ?

[schuettecarsten]

After a restart and a Gravity update to rebuild the database, the error did not occur any longer.

[schuettecarsten]

I updated to 54b4ad93 but I still can see tons of these messages in the logs, even after a restart:

2024-11-08 08:58:54.689 WARNING Tried to access 18434625393987160586 in _findUpstreamID() (/app/src/datastructure.c:155) but next_str_pos is 71334
2024-11-08 08:59:37.262 WARNING Tried to access 18434625393987160586 in _findUpstreamID() (/app/src/datastructure.c:155) but next_str_pos is 71871
2024-11-08 08:59:54.351 WARNING Tried to access 18434625393987160586 in _findUpstreamID() (/app/src/datastructure.c:155) but next_str_pos is 72156

I can also see this mesage:

2024-11-08 09:00:00.724 WARNING Tried to access 18434625393987160586 in resolveAndAddHostname() (/app/src/resolve.c:738) but next_str_pos is 72156
2024-11-08 09:22:51.698 WARNING Tried to access 16773554299861993525 in get_top_upstreams() (/app/src/api/stats.c:631) but next_str_pos is 81182
2024-11-08 09:31:35.089 WARNING Tried to access 18434625393987160586 in queries_to_database() (/app/src/database/query-table.c:1508) but next_str_pos is 85145

[DL6ER]

Interesting, but now we see it in other places, too, suggesting there isn't something wrong with upstreams but with memory allocation overall.

Please enable shared memory debugging using

pihole-FTL --config debug.shmem true

inside your container.

This will make FTL.log a lot more verbose. Then, when you see similar messages, e.g.

2024-11-08 09:00:00.724 WARNING Tried to access 18434625393987160586 in resolveAndAddHostname() (/app/src/resolve.c:738) but next_str_pos is 72156

it'd be interesting if this huge index was mentioned elsewhere/before in the file. Use

grep 18434625393987160586 /var/log/pihole/FTL.log*

to check this (obviously you'll have to replace the number with the particular one that shows up in future warnings).

[schuettecarsten]

I run pihole with debug.shmem active for some time now and was not yet able to reproduce the issue.

[DL6ER]

How often did you see it before? I do hope it is not one of these hard-to-find bugs where enabling debug printing alone already helps... I will attach valgrind to my own pihole-FTL process to see if anything suspicious is found. I would not (yet) recommend you doing the same as interpreting the results is pretty difficult even when you run it on your own machine and have all the logs at hand.

[DL6ER]

Please try again on the latest :nightly container.