search

pi-hole / FTL

The Pi-hole FTL engine
https://pi-hole.net
Other
1.38k stars 196 forks source link

FTL crashes randomly and has to be restarted manually #521

Closed code-kungfu closed 5 years ago

code-kungfu commented 5 years ago

In raising this issue, I confirm the following (please check boxes, eg [X]) Failure to fill the template will close your issue:

How familiar are you with the codebase?:

{1}

[BUG | ISSUE] Expected Behaviour: FTL should not crash

[BUG | ISSUE] Actual Behaviour: After updating to 4.2.2 FTL crashes because a shared memory object cannot be found when trying to resize /FTL-strings FTL can only be returned into a working state by logging in to the admin interface and issue Restart DNS

[BUG | ISSUE] Steps to reproduce: Happens randomly.

-

-

Log file output [if available]

[2019-02-23 14:22:22.354 11512] ########## FTL started! ##########
[2019-02-23 14:22:22.354 11512] FTL branch: master
[2019-02-23 14:22:22.354 11512] FTL version: v4.2.2
[2019-02-23 14:22:22.354 11512] FTL commit: 4a8003c
[2019-02-23 14:22:22.354 11512] FTL date: 2019-02-18 18:30:16 +0100
[2019-02-23 14:22:22.354 11512] FTL user: pihole
[2019-02-23 14:22:22.355 11512] Starting config file parsing (/etc/pihole/pihole-FTL.conf)
[2019-02-23 14:22:22.355 11512]    SOCKET_LISTENING: only local
[2019-02-23 14:22:22.355 11512]    AAAA_QUERY_ANALYSIS: Show AAAA queries
[2019-02-23 14:22:22.355 11512]    MAXDBDAYS: max age for stored queries is 365 days
[2019-02-23 14:22:22.355 11512]    RESOLVE_IPV6: Resolve IPv6 addresses
[2019-02-23 14:22:22.355 11512]    RESOLVE_IPV4: Resolve IPv4 addresses
[2019-02-23 14:22:22.355 11512]    DBINTERVAL: saving to DB file every minute
[2019-02-23 14:22:22.355 11512]    DBFILE: Using /etc/pihole/pihole-FTL.db
[2019-02-23 14:22:22.355 11512]    MAXLOGAGE: Importing up to 24.0 hours of log data
[2019-02-23 14:22:22.355 11512]    PRIVACYLEVEL: Set to 0
[2019-02-23 14:22:22.355 11512]    IGNORE_LOCALHOST: Show queries from localhost
[2019-02-23 14:22:22.355 11512]    BLOCKINGMODE: Null IPs for blocked domains
[2019-02-23 14:22:22.355 11512]    REGEX_DEBUGMODE: Inactive
[2019-02-23 14:22:22.355 11512]    ANALYZE_ONLY_A_AND_AAAA: Disabled. Analyzing all queries
[2019-02-23 14:22:22.355 11512]    DBIMPORT: Importing history from database
[2019-02-23 14:22:22.355 11512]    PIDFILE: Using /var/run/pihole-FTL.pid
[2019-02-23 14:22:22.355 11512]    PORTFILE: Using /var/run/pihole-FTL.port
[2019-02-23 14:22:22.355 11512]    SOCKETFILE: Using /var/run/pihole/FTL.sock
[2019-02-23 14:22:22.355 11512]    WHITELISTFILE: Using /etc/pihole/whitelist.txt
[2019-02-23 14:22:22.355 11512]    BLACKLISTFILE: Using /etc/pihole/black.list
[2019-02-23 14:22:22.355 11512]    GRAVITYFILE: Using /etc/pihole/gravity.list
[2019-02-23 14:22:22.356 11512]    REGEXLISTFILE: Using /etc/pihole/regex.list
[2019-02-23 14:22:22.356 11512]    SETUPVARSFILE: Using /etc/pihole/setupVars.conf
[2019-02-23 14:22:22.356 11512]    AUDITLISTFILE: Using /etc/pihole/auditlog.list
[2019-02-23 14:22:22.356 11512] Finished config file parsing
[2019-02-23 14:22:22.357 11512] Database successfully initialized
[2019-02-23 14:22:22.357 11512] New forward server: 1.0.0.1 (0/4096)
[2019-02-23 14:22:22.358 11512] New forward server: 1.1.1.1 (1/4096)
[2019-02-23 14:22:22.360 11512] New forward server: 10.16.100.1 (2/4096)
[2019-02-23 14:22:22.362 11512] Resizing "/FTL-strings" from 4096 to 8192
[2019-02-23 14:22:22.365 11512] Resizing "/FTL-queries" from 294912 to 589824
[2019-02-23 14:22:22.370 11512] Resizing "/FTL-strings" from 8192 to 12288
[2019-02-23 14:22:22.375 11512] Resizing "/FTL-queries" from 589824 to 884736
[2019-02-23 14:22:22.378 11512] Resizing "/FTL-strings" from 12288 to 16384
[2019-02-23 14:22:22.381 11512] Resizing "/FTL-strings" from 16384 to 20480
[2019-02-23 14:22:22.385 11512] Resizing "/FTL-queries" from 884736 to 1179648
[2019-02-23 14:22:22.395 11512] Resizing "/FTL-strings" from 20480 to 24576
[2019-02-23 14:22:22.396 11512] Resizing "/FTL-queries" from 1179648 to 1474560
[2019-02-23 14:22:22.405 11512] New forward server: 127.0.0.1 (3/4096)
[2019-02-23 14:22:22.405 11512] Resizing "/FTL-strings" from 24576 to 28672
[2019-02-23 14:22:22.408 11512] Resizing "/FTL-queries" from 1474560 to 1769472
[2019-02-23 14:22:22.417 11512] Resizing "/FTL-strings" from 28672 to 32768
[2019-02-23 14:22:22.422 11512] Resizing "/FTL-queries" from 1769472 to 2064384
[2019-02-23 14:22:22.429 11512] Resizing "/FTL-strings" from 32768 to 36864
[2019-02-23 14:22:22.435 11512] Resizing "/FTL-queries" from 2064384 to 2359296
[2019-02-23 14:22:22.443 11512] Resizing "/FTL-queries" from 2359296 to 2654208
[2019-02-23 14:22:22.451 11512] Resizing "/FTL-queries" from 2654208 to 2949120
[2019-02-23 14:22:22.454 11512] Resizing "/FTL-strings" from 36864 to 40960
[2019-02-23 14:22:22.460 11512] Resizing "/FTL-queries" from 2949120 to 3244032
[2019-02-23 14:22:22.470 11512] Resizing "/FTL-queries" from 3244032 to 3538944
[2019-02-23 14:22:22.470 11512] Imported 45143 queries from the long-term database
[2019-02-23 14:22:22.471 11512]  -> Total DNS queries: 45143
[2019-02-23 14:22:22.471 11512]  -> Cached DNS queries: 16447
[2019-02-23 14:22:22.471 11512]  -> Forwarded DNS queries: 14987
[2019-02-23 14:22:22.471 11512]  -> Exactly blocked DNS queries: 13707
[2019-02-23 14:22:22.471 11512]  -> Unknown DNS queries: 2
[2019-02-23 14:22:22.471 11512]  -> Unique domains: 1357
[2019-02-23 14:22:22.471 11512]  -> Unique clients: 21
[2019-02-23 14:22:22.471 11512]  -> Known forward destinations: 4
[2019-02-23 14:22:22.471 11512] Successfully accessed setupVars.conf
[2019-02-23 14:22:22.479 11514] PID of FTL process: 11514
[2019-02-23 14:22:22.479 11514] Listening on port 4711 for incoming IPv4 telnet connections
[2019-02-23 14:22:22.479 11514] Listening on port 4711 for incoming IPv6 telnet connections
[2019-02-23 14:22:22.479 11514] Listening on Unix socket
[2019-02-23 14:22:22.480 11514] Compiled 0 Regex filters and 20 whitelisted domains in 0.1 msec (0 errors)
[2019-02-23 14:22:22.480 11514] /etc/pihole/black.list: parsed 2 domains (took 0.0 ms)
[2019-02-23 14:22:29.073 11514] /etc/pihole/gravity.list: parsed 1414973 domains (took 6593.2 ms)
[2019-02-23 18:50:24.633 11514] Resizing "/FTL-strings" from 40960 to 45056
[2019-02-23 18:50:24.633 11514] FATAL: realloc_shm(): Failed to open shared memory object "/FTL-strings": No such file or directory

Device specifics

Hardware Type: x86-64 in a KVM virtual machine. OS: Devuan Linux 2.0 ASCII (Based on Debian 9.0 Stretch WITHOUT SystemD)

This template was created based on the work of udemy-dl.

DL6ER commented 5 years ago

This is likely a duplicate of #496. I know that this issue got quite hard to read.

Please try

pihole checkout ftl hotfix/v4.2.3
code-kungfu commented 5 years ago

@DL6ER Thanks. I did go through #496 but it seemed like it wasn't directly related to my issue, hence why I created a new one. I'll try the hotfix ASAP

DL6ER commented 5 years ago

Yeah, I see

[2019-02-23 18:50:24.633 11514] Resizing "/FTL-strings" from 40960 to 45056
[2019-02-23 18:50:24.633 11514] FATAL: realloc_shm(): Failed to open shared memory object "/FTL-strings": No such file or directory

and after rethinking, I agree that it might not be related as only one PID is accessing/resizing the shm object as it seems. @Mcat12 will be interested in this.

code-kungfu commented 5 years ago

@DL6ER I did apply the hotfix now, I'll update with my findings.

code-kungfu commented 5 years ago

Hotfix 4.2.3 doesn't fix the issue with FTL-strings

FTL just crashed twice with the same error as logged in this thread.

AzureMarker commented 5 years ago

What is the output of this command both after starting FTL and after it crashes?

ls -lh /dev/shm/FTL-*
code-kungfu commented 5 years ago

@Mcat12 Output of the command while running normally:

pihole@sinkhole:/var/log$ ls -lh /dev/shm/FTL-*
-rw------- 1 pihole pihole 2,5M Feb 23 23:27 /dev/shm/FTL-clients
-rw------- 1 pihole pihole  108 Feb 23 23:27 /dev/shm/FTL-counters
-rw------- 1 pihole pihole 128K Feb 23 23:27 /dev/shm/FTL-domains
-rw------- 1 pihole pihole 160K Feb 23 23:27 /dev/shm/FTL-forwarded
-rw------- 1 pihole pihole   48 Feb 23 23:27 /dev/shm/FTL-lock
-rw------- 1 pihole pihole  12K Feb 23 23:27 /dev/shm/FTL-overTime
-rw------- 1 pihole pihole 3,1M Feb 23 23:59 /dev/shm/FTL-queries
-rw------- 1 pihole pihole   12 Feb 23 23:27 /dev/shm/FTL-settings
-rw------- 1 pihole pihole  48K Feb 23 23:27 /dev/shm/FTL-strings

FTL hasn't crashed (yet), I'll update with output as soon as the next crash occurs.

code-kungfu commented 5 years ago

Okay, just had a crash 10 minutes ago of writing. Seems like the shared memory objects gets killed completely.

pihole@sinkhole:/var/log$ ls -lh /dev/shm/FTL-*
ls: cannot access '/dev/shm/FTL-*': No such file or directory
DL6ER commented 5 years ago

FTL is never unlinking these files until it terminates per user request. What software is installed on the same machine that might be messing around with shared memory?

code-kungfu commented 5 years ago

@DL6ER The only other software running, besides the base Devuan system is cloudflared to perform DoH.

This morning was really bad. FTL crashed 9 times over a period of 4 hours. One of the times 3 in a row.

dschaper commented 5 years ago

What is the output from sudo mount and free -h?

code-kungfu commented 5 years ago

@dschaper As per your request:

pihole@sinkhole:~$ sudo mount
sysfs on /sys type sysfs (rw,nosuid,nodev,noexec,relatime)
proc on /proc type proc (rw,nosuid,nodev,noexec,relatime)
udev on /dev type devtmpfs (rw,nosuid,relatime,size=1015136k,nr_inodes=253784,mode=755)
devpts on /dev/pts type devpts (rw,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=000)
tmpfs on /run type tmpfs (rw,nosuid,noexec,relatime,size=205248k,mode=755)
/dev/vda1 on / type ext4 (rw,relatime,errors=remount-ro,data=ordered)
tmpfs on /run/lock type tmpfs (rw,nosuid,nodev,noexec,relatime,size=5120k)
pstore on /sys/fs/pstore type pstore (rw,relatime)
tmpfs on /run/shm type tmpfs (rw,nosuid,nodev,noexec,relatime,size=829300k)
tmpfs on /sys/fs/cgroup type tmpfs (rw,nosuid,nodev,noexec,mode=755)
cgroup on /sys/fs/cgroup/elogind type cgroup (rw,nosuid,nodev,noexec,relatime,xattr,release_agent=/usr/lib/elogind/elogind-cgroups-agent,name=elogind)
tmpfs on /run/user/1000 type tmpfs (rw,nosuid,nodev,relatime,size=205244k,mode=700,uid=1000,gid=1000)
pihole@sinkhole:~$ free -h
              total        used        free      shared  buff/cache   available
Mem:           2,0G        219M        1,5G         12M        260M        1,6G
Swap:          2,0G          0B        2,0G
dschaper commented 5 years ago

Looks like there is a size limitation on the shared memory directory:

tmpfs on /run/shm type tmpfs (rw,nosuid,nodev,noexec,relatime,size=829300k)

Something (possibly init) is reaping files in that directory.

dschaper commented 5 years ago

Can you check /etc/default/tmpfs and see what is listed for SHM_* values?

code-kungfu commented 5 years ago

Output of df -k /dev/shm

pihole@sinkhole:/etc/init.d$ df -k /dev/shm
Filesystem     1K-blocks  Used Available Use% Mounted on
tmpfs             829300  3668    825632   1% /run/shm

Output of /etc/default/tmpfs

pihole@sinkhole:/etc/init.d$ cat /etc/default/tmpfs
#
# Configuration for tmpfs filesystems mounted in early boot, before
# filesystems from /etc/fstab are mounted.  For information about
# these variables see the tmpfs(5) manual page.

# /run is always mounted as a tmpfs on systems which support tmpfs
# mounts.

# mount /run/lock as a tmpfs (separately from /run).  Defaults to yes;
# set to no to disable (/run/lock will then be part of the /run tmpfs,
# if available).
#RAMLOCK=yes

# mount /run/shm as a tmpfs (separately from /run).  Defaults to yes;
# set to no to disable (/run/shm will then be part of the /run tmpfs,
# if available).
#RAMSHM=yes

# mount /tmp as a tmpfs.  Defaults to no; set to yes to enable (/tmp
# will be part of the root filesystem if disabled).  /tmp may also be
# configured to be a separate mount in /etc/fstab.
#RAMTMP=no

# Size limits.  Please see tmpfs(5) for details on how to configure
# tmpfs size limits.
#TMPFS_SIZE=20%VM
#RUN_SIZE=10%
#LOCK_SIZE=5242880 # 5MiB
#SHM_SIZE=
#TMP_SIZE=

# Mount tmpfs on /tmp if there is less than the limit size (in kiB) on
# the root filesystem (overriding RAMTMP).
#TMP_OVERFLOW_LIMIT=1024
dschaper commented 5 years ago

Try uncommenting #SHM_SIZE to allow no restrictions on that directory and reboot the node. That should stop files being reaped in that directory.

code-kungfu commented 5 years ago

@dschaper Done. We'll see how it goes.

Thank you for your help so far.

code-kungfu commented 5 years ago

@dschaper That did only last for like 6 hours. Though it crashed at FLT-Queries instead.

[2019-02-24 12:44:34.404 2914] ########## FTL started! ##########
[2019-02-24 12:44:34.405 2914] FTL branch: hotfix/v4.2.3
[2019-02-24 12:44:34.405 2914] FTL version:
[2019-02-24 12:44:34.405 2914] FTL commit: a11d3dd
[2019-02-24 12:44:34.405 2914] FTL date: 2019-02-21 18:20:51 -0800
[2019-02-24 12:44:34.405 2914] FTL user: pihole
[2019-02-24 12:44:34.405 2914] Starting config file parsing (/etc/pihole/pihole-FTL.conf)
[2019-02-24 12:44:34.405 2914]    SOCKET_LISTENING: only local
[2019-02-24 12:44:34.405 2914]    AAAA_QUERY_ANALYSIS: Show AAAA queries
[2019-02-24 12:44:34.405 2914]    MAXDBDAYS: max age for stored queries is 365 days
[2019-02-24 12:44:34.405 2914]    RESOLVE_IPV6: Resolve IPv6 addresses
[2019-02-24 12:44:34.405 2914]    RESOLVE_IPV4: Resolve IPv4 addresses
[2019-02-24 12:44:34.405 2914]    DBINTERVAL: saving to DB file every minute
[2019-02-24 12:44:34.405 2914]    DBFILE: Using /etc/pihole/pihole-FTL.db
[2019-02-24 12:44:34.405 2914]    MAXLOGAGE: Importing up to 24.0 hours of log data
[2019-02-24 12:44:34.405 2914]    PRIVACYLEVEL: Set to 0
[2019-02-24 12:44:34.405 2914]    IGNORE_LOCALHOST: Show queries from localhost
[2019-02-24 12:44:34.405 2914]    BLOCKINGMODE: Null IPs for blocked domains
[2019-02-24 12:44:34.406 2914]    REGEX_DEBUGMODE: Inactive
[2019-02-24 12:44:34.406 2914]    ANALYZE_ONLY_A_AND_AAAA: Disabled. Analyzing all queries
[2019-02-24 12:44:34.406 2914]    DBIMPORT: Importing history from database
[2019-02-24 12:44:34.406 2914]    PIDFILE: Using /var/run/pihole-FTL.pid
[2019-02-24 12:44:34.406 2914]    PORTFILE: Using /var/run/pihole-FTL.port
[2019-02-24 12:44:34.406 2914]    SOCKETFILE: Using /var/run/pihole/FTL.sock
[2019-02-24 12:44:34.406 2914]    WHITELISTFILE: Using /etc/pihole/whitelist.txt
[2019-02-24 12:44:34.406 2914]    BLACKLISTFILE: Using /etc/pihole/black.list
[2019-02-24 12:44:34.406 2914]    GRAVITYFILE: Using /etc/pihole/gravity.list
[2019-02-24 12:44:34.406 2914]    REGEXLISTFILE: Using /etc/pihole/regex.list
[2019-02-24 12:44:34.406 2914]    SETUPVARSFILE: Using /etc/pihole/setupVars.conf
[2019-02-24 12:44:34.406 2914]    AUDITLISTFILE: Using /etc/pihole/auditlog.list
[2019-02-24 12:44:34.406 2914] Finished config file parsing
[2019-02-24 12:44:34.411 2914] Database successfully initialized
[2019-02-24 12:44:34.411 2914] New forward server: 127.0.0.1 (0/4096)
[2019-02-24 12:44:34.414 2914] Resizing "/FTL-strings" from 4096 to 8192
[2019-02-24 12:44:34.420 2914] New forward server: 10.16.100.1 (1/4096)
[2019-02-24 12:44:34.427 2914] Resizing "/FTL-strings" from 8192 to 12288
[2019-02-24 12:44:34.428 2914] Resizing "/FTL-queries" from 294912 to 589824
[2019-02-24 12:44:34.445 2914] Resizing "/FTL-queries" from 589824 to 884736
[2019-02-24 12:44:34.462 2914] Resizing "/FTL-strings" from 12288 to 16384
[2019-02-24 12:44:34.462 2914] Resizing "/FTL-queries" from 884736 to 1179648
[2019-02-24 12:44:34.467 2914] Resizing "/FTL-strings" from 16384 to 20480
[2019-02-24 12:44:34.467 2914] Resizing "/FTL-strings" from 20480 to 24576
[2019-02-24 12:44:34.468 2914] Resizing "/FTL-strings" from 24576 to 28672
[2019-02-24 12:44:34.469 2914] Resizing "/FTL-strings" from 28672 to 32768
[2019-02-24 12:44:34.486 2914] Resizing "/FTL-queries" from 1179648 to 1474560
[2019-02-24 12:44:34.500 2914] Resizing "/FTL-strings" from 32768 to 36864
[2019-02-24 12:44:34.510 2914] Resizing "/FTL-queries" from 1474560 to 1769472
[2019-02-24 12:44:34.534 2914] Resizing "/FTL-queries" from 1769472 to 2064384
[2019-02-24 12:44:34.542 2914] Resizing "/FTL-strings" from 36864 to 40960
[2019-02-24 12:44:34.563 2914] Resizing "/FTL-queries" from 2064384 to 2359296
[2019-02-24 12:44:34.573 2914] Resizing "/FTL-strings" from 40960 to 45056
[2019-02-24 12:44:34.599 2914] Resizing "/FTL-queries" from 2359296 to 2654208
[2019-02-24 12:44:34.619 2914] Resizing "/FTL-queries" from 2654208 to 2949120
[2019-02-24 12:44:34.621 2914] Resizing "/FTL-strings" from 45056 to 49152
[2019-02-24 12:44:34.645 2914] Resizing "/FTL-queries" from 2949120 to 3244032
[2019-02-24 12:44:34.676 2914] Resizing "/FTL-queries" from 3244032 to 3538944
[2019-02-24 12:44:34.700 2914] Resizing "/FTL-strings" from 49152 to 53248
[2019-02-24 12:44:34.700 2914] Resizing "/FTL-queries" from 3538944 to 3833856
[2019-02-24 12:44:34.702 2914] Imported 49802 queries from the long-term database
[2019-02-24 12:44:34.707 2914]  -> Total DNS queries: 49802
[2019-02-24 12:44:34.707 2914]  -> Cached DNS queries: 17253
[2019-02-24 12:44:34.707 2914]  -> Forwarded DNS queries: 16435
[2019-02-24 12:44:34.707 2914]  -> Exactly blocked DNS queries: 16114
[2019-02-24 12:44:34.707 2914]  -> Unknown DNS queries: 0
[2019-02-24 12:44:34.707 2914]  -> Unique domains: 1633
[2019-02-24 12:44:34.707 2914]  -> Unique clients: 18
[2019-02-24 12:44:34.707 2914]  -> Known forward destinations: 2
[2019-02-24 12:44:34.707 2914] Successfully accessed setupVars.conf
[2019-02-24 12:44:34.723 2916] PID of FTL process: 2916
[2019-02-24 12:44:34.723 2916] Listening on port 4711 for incoming IPv4 telnet connections
[2019-02-24 12:44:34.723 2916] Listening on port 4711 for incoming IPv6 telnet connections
[2019-02-24 12:44:34.723 2916] Listening on Unix socket
[2019-02-24 12:44:34.724 2916] Compiled 0 Regex filters and 20 whitelisted domains in 0.1 msec (0 errors)
[2019-02-24 12:44:34.724 2916] /etc/pihole/black.list: parsed 2 domains (took 0.0 ms)
[2019-02-24 12:44:47.346 2916] /etc/pihole/gravity.list: parsed 1416582 domains (took 12622.0 ms)
[2019-02-24 17:56:46.619 2916] Resizing "/FTL-queries" from 3833856 to 4128768
[2019-02-24 17:56:46.619 2916] FATAL: realloc_shm(): Failed to open shared memory object "/FTL-queries": No such file or directory
dschaper commented 5 years ago

Is there anything in the system logs that mentions the shared memory directory? Possibly a cron job or something like that? And check to see if there are any mentions for pihole-FTL as well.

I'd grep /var/log/messages or /var/log/syslog for shm to see.

code-kungfu commented 5 years ago

There isn't any mentions of shm in either logfiles.

The only references to pihole-FTL in syslog is when I've reloaded after the crash.

DL6ER commented 5 years ago

@code-kungfu You tried commenting SHM_SIZE to remove the size restriction. This either didn't work as intended or there is still another cron job or something similar (maybe anacron) that periodically wipes out the directory, effectively stealing pihole-FTL its data.

Check if there is something interesting in /etc/crontab or /etc/cron.daily/, /etc/cron.hourly and siblings.

liang-hiwin commented 5 years ago

How to start FTLDNS?

liang-hiwin commented 5 years ago

启动FTL后和崩溃后该命令的输出是什么？

ls -lh /dev/shm/FTL-*

root@raspberrypi:/home/pi# pihole-FTL

dnsmasq: failed to create listening socket for port 53: Address already in use root@raspberrypi:/home/pi#

liang-hiwin commented 5 years ago

[2019-03-11 00:17:55.091 2073] -> Cached DNS queries: 1002 [2019-03-11 00:17:55.091 2073] -> Forwarded DNS queries: 45062 [2019-03-11 00:17:55.091 2073] -> Exactly blocked DNS queries: 87 [2019-03-11 00:17:55.091 2073] -> Unknown DNS queries: 20 [2019-03-11 00:17:55.091 2073] -> Unique domains: 619 [2019-03-11 00:17:55.091 2073] -> Unique clients: 5 [2019-03-11 00:17:55.091 2073] -> Known forward destinations: 5 [2019-03-11 00:17:55.091 2073] Successfully accessed setupVars.conf [2019-03-11 00:41:22.576 1423] Resizing "/FTL-strings" from 12288 to 16384 [2019-03-11 00:41:22.576 1423] FATAL: realloc_shm(): Failed to open shared memory object "/FTL-strings": Permission denied

dschaper commented 5 years ago

@thb007 Open a new issue, this issue does not relate to you.

webash commented 5 years ago

I'm also having this issue; at 11:40am today it suddenly crashed when attempting to resize FTL-strings, then all further resizing operations were constantly failing, flooding the log to 800MB with thousands of entries

[2019-04-27 11:40:02.552] Resizing "/FTL-overTime" from 212992 to 425984
[2019-04-27 11:40:02.552] FATAL ERROR: Trying to access overTime[4094], but magic byte is 0
[2019-04-27 11:40:02.552]              found in findOverTimeID() (datastructure.c:36)
[2019-04-27 11:40:02.555] Resizing "/FTL-client-0" from 16384 to 32768
[2019-04-27 11:40:02.555] realloc_shm(): Failed to open shared memory object "/FTL-client-0": No such file or directory
[2019-04-27 11:40:02.556] Resizing "/FTL-client-1" from 16384 to 32768
[2019-04-27 11:40:02.556] realloc_shm(): Failed to open shared memory object "/FTL-client-1": No such file or directory
[2019-04-27 11:40:02.556] Resizing "/FTL-client-2" from 16384 to 32768
[2019-04-27 11:40:02.556] realloc_shm(): Failed to open shared memory object "/FTL-client-2": No such file or directory
[2019-04-27 11:40:02.556] Resizing "/FTL-client-3" from 16384 to 32768
[2019-04-27 11:40:02.556] realloc_shm(): Failed to open shared memory object "/FTL-client-3": No such file or directory
[2019-04-27 11:40:02.556] Resizing "/FTL-client-4" from 16384 to 32768
[2019-04-27 11:40:02.556] realloc_shm(): Failed to open shared memory object "/FTL-client-4": No such file or directory
[2019-04-27 11:40:02.556] Resizing "/FTL-client-5" from 16384 to 32768
[2019-04-27 11:40:02.557] realloc_shm(): Failed to open shared memory object "/FTL-client-5": No such file or directory
[2019-04-27 11:40:02.557] Resizing "/FTL-client-6" from 16384 to 32768
[2019-04-27 11:40:02.557] realloc_shm(): Failed to open shared memory object "/FTL-client-6": No such file or directory
[2019-04-27 11:40:02.557] Resizing "/FTL-client-7" from 16384 to 32768
[2019-04-27 11:40:02.557] realloc_shm(): Failed to open shared memory object "/FTL-client-7": No such file or directory
[2019-04-27 11:40:02.557] Resizing "/FTL-client-8" from 16384 to 32768
[2019-04-27 11:40:02.557] realloc_shm(): Failed to open shared memory object "/FTL-client-8": No such file or directory
[2019-04-27 11:40:02.557] Resizing "/FTL-client-9" from 16384 to 32768
[2019-04-27 11:40:02.557] realloc_shm(): Failed to open shared memory object "/FTL-client-9": No such file or directory
...continues like this for 800MB...
[2019-04-27 11:59:02.593] realloc_shm(): Failed to open shared memory object "/FTL-client-25": N
o such file or directory
[2019-04-27 11:59:02.593] Resizing "/FTL-client-26" from 1589248 to 1622016
[2019-04-27 11:59:02.594] realloc_shm(): Failed to open shared memory object "/FTL-client-26": N
o such file or directory
[2019-04-27 11:59:02.594] !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
!!!!
[2019-04-27 11:59:02.594] ---------------------------->  FTL crashed!  <------------------------
----
[2019-04-27 11:59:02.594] !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
!!!!
[2019-04-27 11:59:02.594] Please report a bug at https://github.com/pi-hole/FTL/issues
[2019-04-27 11:59:02.594] and include in your report already the following details:

[2019-04-27 11:59:02.594] FTL has been running for 2370897 seconds
[2019-04-27 11:59:02.594] FTL branch: master
[2019-04-27 11:59:02.600] FTL version: v4.2.1
[2019-04-27 11:59:02.601] FTL commit: 5f98312
[2019-04-27 11:59:02.601] FTL date: 2019-02-06 18:36:55 -0800
[2019-04-27 11:59:02.601] FTL user: started as pihole, ended as pihole
[2019-04-27 11:59:02.601] Received signal: Segmentation fault
[2019-04-27 11:59:02.601]      at address: 1918414800
[2019-04-27 11:59:02.601]      with code: SEGV_MAPERR (Address not mapped to object)
[2019-04-27 11:59:02.612] Backtrace:
[2019-04-27 11:59:02.613] B[0000]: /usr/bin/pihole-FTL(+0x1a3e0) [0x42a3e0]
[2019-04-27 11:59:02.613] B[0001]: /lib/arm-linux-gnueabihf/libc.so.6(__default_rt_sa_restorer+0
) [0x76e026c0]
[2019-04-27 11:59:02.613] B[0002]: /usr/bin/pihole-FTL(findOverTimeID+0x13d) [0x429d36]
[2019-04-27 11:59:02.613] B[0003]: /usr/bin/pihole-FTL(FTL_cache+0x205) [0x433036]
[2019-04-27 11:59:02.613] B[0004]: /usr/bin/pihole-FTL(answer_request+0x767) [0x44913c]
[2019-04-27 11:59:02.613] B[0005]: /usr/bin/pihole-FTL(receive_query+0x369) [0x44150e]
[2019-04-27 11:59:02.613] B[0006]: /usr/bin/pihole-FTL(+0x3edee) [0x44edee]
[2019-04-27 11:59:02.613] B[0007]: /usr/bin/pihole-FTL(main_dnsmasq+0xa33) [0x44ff70]
[2019-04-27 11:59:02.613] B[0008]: /usr/bin/pihole-FTL(main+0x87) [0x428d8c]
[2019-04-27 11:59:02.613] B[0009]: /lib/arm-linux-gnueabihf/libc.so.6(__libc_start_main+0x114) [
0x76dec678]
[2019-04-27 11:59:02.613] Thank you for helping us to improve our FTL engine!
[2019-04-27 11:59:02.613] FTL terminated!

Had to reboot the system to bring it back online, as restarting pihole-FTL did nothing.

I've dumped system mount point sizes, and nothing is full:

ashley@agn-stash01-lon:/var/log $ sudo df -h
[sudo] password for ashley:
Filesystem      Size  Used Avail Use% Mounted on
/dev/root        15G  5.4G  8.7G  39% /
devtmpfs        460M     0  460M   0% /dev
tmpfs           464M  2.8M  461M   1% /dev/shm
tmpfs           464M   19M  446M   4% /run
tmpfs           5.0M  4.0K  5.0M   1% /run/lock
tmpfs           464M     0  464M   0% /sys/fs/cgroup
/dev/mmcblk0p1   43M   22M   21M  52% /boot
/dev/sda3       2.5T  973G  1.5T  41% /media/lon-ashmedia-02
tmpfs            93M     0   93M   0% /run/user/998
tmpfs            93M     0   93M   0% /run/user/1001

mounts:

ashley@agn-stash01-lon:/var/log $ sudo mount
/dev/mmcblk0p2 on / type ext4 (rw,noatime,data=ordered)
devtmpfs on /dev type devtmpfs (rw,relatime,size=470116k,nr_inodes=117529,mode=755)
sysfs on /sys type sysfs (rw,nosuid,nodev,noexec,relatime)
proc on /proc type proc (rw,relatime)
tmpfs on /dev/shm type tmpfs (rw,nosuid,nodev)
devpts on /dev/pts type devpts (rw,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=000)
tmpfs on /run type tmpfs (rw,nosuid,nodev,mode=755)
tmpfs on /run/lock type tmpfs (rw,nosuid,nodev,noexec,relatime,size=5120k)
tmpfs on /sys/fs/cgroup type tmpfs (ro,nosuid,nodev,noexec,mode=755)
cgroup on /sys/fs/cgroup/systemd type cgroup (rw,nosuid,nodev,noexec,relatime,xattr,release_agent=/lib/systemd/systemd-cgroups-agent,name=systemd)
cgroup on /sys/fs/cgroup/freezer type cgroup (rw,nosuid,nodev,noexec,relatime,freezer)
cgroup on /sys/fs/cgroup/cpu,cpuacct type cgroup (rw,nosuid,nodev,noexec,relatime,cpu,cpuacct)
cgroup on /sys/fs/cgroup/cpuset type cgroup (rw,nosuid,nodev,noexec,relatime,cpuset)
cgroup on /sys/fs/cgroup/blkio type cgroup (rw,nosuid,nodev,noexec,relatime,blkio)
cgroup on /sys/fs/cgroup/net_cls type cgroup (rw,nosuid,nodev,noexec,relatime,net_cls)
cgroup on /sys/fs/cgroup/devices type cgroup (rw,nosuid,nodev,noexec,relatime,devices)
systemd-1 on /proc/sys/fs/binfmt_misc type autofs (rw,relatime,fd=30,pgrp=1,timeout=0,minproto=5,maxproto=5,direct)
mqueue on /dev/mqueue type mqueue (rw,relatime)
debugfs on /sys/kernel/debug type debugfs (rw,relatime)
sunrpc on /run/rpc_pipefs type rpc_pipefs (rw,relatime)
configfs on /sys/kernel/config type configfs (rw,relatime)
/dev/mmcblk0p1 on /boot type vfat (rw,relatime,fmask=0022,dmask=0022,codepage=437,iocharset=ascii,shortname=mixed,errors=remount-ro)
binfmt_misc on /proc/sys/fs/binfmt_misc type binfmt_misc (rw,relatime)
tmpfs on /run/user/998 type tmpfs (rw,nosuid,nodev,relatime,size=94944k,mode=700,uid=998,gid=995)
tmpfs on /run/user/1001 type tmpfs (rw,nosuid,nodev,relatime,size=94944k,mode=700,uid=1001,gid=1001)

Running on Raspberry Pi Model 3B+

ashley@agn-stash01-lon:/var/log $ sudo lsb_release -a
No LSB modules are available.
Distributor ID: Raspbian
Description:    Raspbian GNU/Linux 9.8 (stretch)
Release:        9.8
Codename:       stretch

Versions: Pi-hole Version v4.2.2 Web Interface Version v4.2 FTL Version v4.2.3

dschaper commented 5 years ago

Please run pihole -up to get the latest released versions that fix this issue. If you have futher issues, please open an new topic, filling out the template with the requested information.

dschaper commented 5 years ago

[2019-04-27 11:59:02.600] FTL version: v4.2.1 This is an outdated version.

webash commented 5 years ago

Not sure why the log is showing that version, per the bottom of my comment, these are versions I'm running, as copied from the bottom of the admin portal: Pi-hole Version v4.2.2 Web Interface Version v4.2 FTL Version v4.2.3

ashley@agn-stash01-lon:~ $ sudo pihole -up
  [i] Checking for updates...
  [i] Pi-hole Core:     up to date
  [i] Web Interface:    up to date
  [i] FTL:              up to date

  [✓] Everything is up to date!
dschaper commented 5 years ago

Try checking the actual pihole-FTL binary version, that's the one that is being called to run and that's the one that is actually the outdated version.

which pihole-FTL
<path reported>/pihole-FTL --version
dschaper@nanopineo:~$ which pihole-FTL
/usr/bin/pihole-FTL
dschaper@nanopineo:~$ /usr/bin/pihole-FTL --version
v4.2.3
webash commented 5 years ago 
ashley@agn-stash01-lon:~ $ which pihole-FTL
/usr/bin/pihole-FTL
ashley@agn-stash01-lon:~ $ /usr/bin/pihole-FTL --version
v4.2.3

Seems I must have a different problem to this one, then?

dschaper commented 5 years ago

Check /var/log/pihole-FTL.log and restart Pi-hole. The actual version of the binary will be logged. The issue is that v4.2.1 does have a bug that causes a crash as you reported, but v4.2.3 has it fixed. There no longer is a SHM file per client but instead all clients are stored in a single file.

webash commented 5 years ago

odd... the log is now showing 4.2.3, but I haven't done an update except that 'all clear' one I pasted above.

[2019-04-27 12:01:14.491 747] ########## FTL started! ##########
[2019-04-27 12:01:14.491 747] FTL branch: master
[2019-04-27 12:01:14.491 747] FTL version: v4.2.3

...not sure how the update was applied between me posting that log and me trying the update earlier... I'll assume it is up to date and no longer dying as before. Will come back as it does.

Thanks for your help, appreciated.

DL6ER commented 5 years ago

@webash pihole -r might have downloaded the most recent version if you have used that recently. It checks whether your FTL binary is identical to the most recent one and "re-"downloads the binary if this is not the case. This can be understood as a silent update.