Failed to execute ban (can only concatenate str (not "NoneType") to str) -- family is None using F-ID tags

[ValeryKV]

Environment:

Fail2Ban v0.10.2, installed by apt.
Debian GNU/Linux 10

The issue:

CRITICAL Unable to restore environment

Steps to reproduce

Most possible my server was rebooted between 22:01:15 and 23:07:44, after 193.56.28.0/24 was banned and added into iptables. See logs below. After reboot, iptables did not contain that entry.

Expected behavior

After reboot or systemctl restart fail2ban, fail2ban must work.

/var/log/fail2ban.log file:

2020-12-14 21:31:15,159 fail2ban.filter         [4392]: INFO    [geologger] Found 193.56.28.0/24 - 2020-12-14 21:31:15
2020-12-14 21:31:15,329 fail2ban.actions        [4392]: NOTICE  [geologger] Ban 193.56.28.0/24
2020-12-14 22:01:15,747 fail2ban.filter         [4392]: INFO    [postfix] Found 139.59.114.121 - 2020-12-14 22:01:15
2020-12-14 23:07:44,703 fail2ban.server         [363]: INFO    --------------------------------------------------
2020-12-14 23:07:44,707 fail2ban.server         [363]: INFO    Starting Fail2ban v0.10.2
...
2020-12-15 00:34:29,718 fail2ban.filter         [363]: INFO    [geologger] Found 193.56.28.0/24 - 2020-12-15 00:34:29
2020-12-15 00:34:30,109 fail2ban.actions        [363]: NOTICE  [geologger] Ban 193.56.28.0/24
2020-12-15 00:34:30,109 fail2ban.actions        [363]: ERROR   Failed to execute ban jail 'geologger' action 'iptables-multiport' info 'ActionInfo({'ip': '193.56.28.0/24', 'family': None, 'ip-rev': '', 'ip-host': None, 'fid': '193.56.28.0/24', 'failures': 2, 'time': 1607992469.0, 'matches': 'Dec 15 00:34:29 INFO ...can only concatenate str (not "NoneType") to str
2020-12-15 01:34:30,005 fail2ban.actions        [363]: NOTICE  [geologger] Unban 193.56.28.0/24
2020-12-15 01:34:30,021 fail2ban.utils          [363]: Level 39 7fe1c6bf7098 -- exec: iptables -w -n -L INPUT | grep -q 'f2b-geologger[ \t]'
2020-12-15 01:34:30,021 fail2ban.utils          [363]: ERROR   7fe1c6bf7098 -- returned 1
2020-12-15 01:34:30,021 fail2ban.CommandAction  [363]: ERROR   Invariant check failed. Trying to restore a sane environment
2020-12-15 01:34:30,032 fail2ban.utils          [363]: Level 39 7fe1c6bf7098 -- exec: iptables -w -n -L INPUT | grep -q 'f2b-geologger[ \t]'
2020-12-15 01:34:30,033 fail2ban.utils          [363]: ERROR   7fe1c6bf7098 -- returned 1
2020-12-15 01:34:30,033 fail2ban.CommandAction  [363]: CRITICAL Unable to restore environment
2020-12-15 01:34:30,033 fail2ban.actions        [363]: ERROR   Failed to execute unban jail 'geologger' action 'iptables-multiport' info 'ActionInfo({'ip': '193.56.28.0/24'...: Error banning 193.56.28.0/24
2020-12-15 02:45:53,941 fail2ban.actions        [363]: NOTICE  [geologger] Unban 193.56.28.0/24
2020-12-15 02:45:53,952 fail2ban.utils          [363]: Level 39 7fe1c6bf7098 -- exec: iptables -w -n -L INPUT | grep -q 'f2b-geologger[ \t]'
2020-12-15 02:45:53,952 fail2ban.utils          [363]: ERROR   7fe1c6bf7098 -- returned 1
2020-12-15 02:45:53,952 fail2ban.CommandAction  [363]: ERROR   Invariant check failed. Trying to restore a sane environment
2020-12-15 02:45:53,961 fail2ban.utils          [363]: Level 39 7fe1c6bf7098 -- exec: iptables -w -n -L INPUT | grep -q 'f2b-geologger[ \t]'
2020-12-15 02:45:53,962 fail2ban.utils          [363]: ERROR   7fe1c6bf7098 -- returned 1
2020-12-15 02:45:53,962 fail2ban.CommandAction  [363]: CRITICAL Unable to restore environment

fail2ban debug:

#  fail2ban-client -d | grep geologger
['add', 'geologger', 'auto']
['multi-set', 'geologger', 'addfailregex', ['\\sgeo\\s+.* cidrs=\\([\\d\\./]+:<F-ID>[\\d\\./]+</F-ID>-.* ehlo=1 auth=0/1 rset=1 quit=1 commands=3/4$', '\\sgeo\\s+.* cidrs=\\([\\d\\./]+:<F-ID>[\\d\\./]+</F-ID>-.* ehlo=1 auth=0/1 quit=1 commands=2/3$', '\\sgeo\\s+[^\\(]+\\([^\\)]+?:dch\\) cidrs=\\([\\d\\./]+:<F-ID>[\\d\\./]+</F-ID>-.*?: Invalid user .*? port \\d+$', '\\sgeo\\s+.*:\\) cidrs=\\([\\d\\./]+:<F-ID>[\\d\\./]+</F-ID>-[\\d\\./]+\\) 1 0:.*?: Invalid user .*? port \\d+$', '\\sgeo\\s+.*:\\) cidrs=\\(<F-ID>[\\d\\./]+</F-ID>:[\\d\\./]+-[\\d\\./]+\\) 0 .*?: Invalid user .*? port \\d+$', '\\sgeo\\s+.*:\\) cidrs=\\([\\d\\./]+:[\\d\\./]+-<F-ID>[\\d\\./]+</F-ID>\\) 1 1:.*?: Invalid user .*? port \\d+$', '\\sgeo\\s+.* cidrs=\\([\\d\\./]+:[\\d\\./]+-<F-ID>[\\d\\./]+</F-ID>\\) 1 1: .* pam_unix\\(sshd:auth\\): authentication failure;', '\\sgeo\\s+.* cidrs=\\([\\d\\./]+:<F-ID>[\\d\\./]+</F-ID>-[\\d\\./]+\\) 1 0:.* pam_unix\\(sshd:auth\\): authentication failure;', '\\sgeo\\s+.* cidrs=\\(<F-ID>[\\d\\./]+</F-ID>:[\\d\\./]+-[\\d\\./]+\\) 0 .* pam_unix\\(sshd:auth\\): authentication failure;']]
['set', 'geologger', 'datepattern', '{^LN-BEG}']
['set', 'geologger', 'addlogpath', '/var/log/geologger.log', 'head']
['set', 'geologger', 'logencoding', 'auto']
['set', 'geologger', 'maxretry', 1]
['set', 'geologger', 'findtime', '30m']
['set', 'geologger', 'bantime', '1h']
['set', 'geologger', 'usedns', 'raw']
['set', 'geologger', 'ignorecommand', '']
['set', 'geologger', 'addaction', 'iptables-multiport']
['multi-set', 'geologger', 'action', 'iptables-multiport', [['actionstart', '<iptables> -N f2b-geologger\n<iptables> -A f2b-geologger -j RETURN\n<iptables> -I INPUT -p tcp -m multiport --dports ssh,2999,smtp,465,submission -j f2b-geologger'], ['actionstop', '<iptables> -D INPUT -p tcp -m multiport --dports ssh,2999,smtp,465,submission -j f2b-geologger\n<iptables> -F f2b-geologger\n<iptables> -X f2b-geologger'], ['actionflush', '<iptables> -F f2b-geologger'], ['actioncheck', "<iptables> -n -L INPUT | grep -q 'f2b-geologger[ \\t]'"], ['actionban', '<iptables> -I f2b-geologger 1 -s <ip> -j <blocktype>'], ['actionunban', '<iptables> -D f2b-geologger -s <ip> -j <blocktype>'], ['name', 'geologger'], ['bantime', '1h'], ['port', 'ssh,2999,smtp,465,submission'], ['protocol', 'tcp'], ['chain', '<known/chain>'], ['actname', 'iptables-multiport'], ['blocktype', 'REJECT --reject-with icmp-port-unreachable'], ['returntype', 'RETURN'], ['lockingopt', '-w'], ['iptables', 'iptables <lockingopt>'], ['blocktype?family=inet6', 'REJECT --reject-with icmp6-port-unreachable'], ['iptables?family=inet6', 'ip6tables <lockingopt>']]]
['start', 'geologger']

iptables:

Chain INPUT (policy ACCEPT 0 packets, 0 bytes)
    pkts      bytes target     prot opt in     out     source               destination         
    3981   296245 f2b-geologger  tcp  --  *      *       0.0.0.0/0            0.0.0.0/0            multiport dports 22,2999,25,465,587
Chain f2b-geologger (1 references)
    pkts      bytes target     prot opt in     out     source               destination         
    3975   295941 RETURN     all  --  *      *       0.0.0.0/0            0.0.0.0/0           

[sebres]

May be that are subsequent faults... Which first error do you see in log after 23:07:44?

But something is strange here anyway - your INPUT chain in iptables does contain f2b-geologger, but action check with iptables -w -n -L INPUT | grep -q 'f2b-geologger[ \t]' seems to miss it for some reason (returns 1, must be 0).
But it should find that:

$ echo '3981   296245 f2b-geologger  tcp ...' | grep -q 'f2b-geologger[ \t]'; echo $?
0

Please try this above and iptables -w -n -L INPUT | grep -q 'f2b-geologger[ \t]'; echo $? in shell.
Do you see 0 as return value?

Also I would like to know which shell is default for root (or user fail2ban is working under)

[ValeryKV]

The first error is at 2020-12-15 00:34:30,109 in the log above. That line ends with can only concatenate str (not "NoneType") to str.

After I submitted this bug, I stopped fail2ban, backed up fail2ban.sqlite3, and restarted fail2ban. So now
iptables -w -n -L INPUT | grep -q 'f2b-geologger[ \t]'; echo $? returns 1.

But that did not help me.

Fail2ban.log:

2020-12-18 14:18:26,925 fail2ban.server         [1518]: INFO    --------------------------------------------------
2020-12-18 14:18:26,925 fail2ban.server         [1518]: INFO    Starting Fail2ban v0.10.2
2020-12-18 14:18:26,935 fail2ban.database       [1518]: INFO    Connected to fail2ban persistent database '/var/lib/fail2ban/fail2ban.sqlite3'
2020-12-18 14:18:26,939 fail2ban.database       [1518]: WARNING New database created. Version '2'
2020-12-18 14:18:27,016 fail2ban.jail           [1518]: INFO    Creating new jail 'geologger'
2020-12-18 14:18:27,016 fail2ban.jail           [1518]: INFO    Jail 'geologger' uses pyinotify {}
2020-12-18 14:18:27,021 fail2ban.jail           [1518]: INFO    Initiated 'pyinotify' backend
...
2020-12-18 14:18:27,031 fail2ban.jail           [1518]: INFO    Jail 'geologger' started
2020-12-18 14:21:39,640 fail2ban.filter         [1518]: INFO    [geologger] Found 193.56.28.0/24 - 2020-12-18 14:09:55
2020-12-18 14:21:39,641 fail2ban.filter         [1518]: INFO    [geologger] Found 193.56.28.0/24 - 2020-12-18 14:09:55
2020-12-18 14:21:39,829 fail2ban.actions        [1518]: NOTICE  [geologger] Ban 193.56.28.0/24
2020-12-18 14:21:39,829 fail2ban.actions        [1518]: ERROR   Failed to execute ban jail 'geologger' action 'iptables-multiport' info 'ActionInfo({'ip': '193.56.28.0/24', 'family': None, 'ip-rev': '', 'ip-host': None, 'fid': '$
2020-12-18 14:41:20,918 fail2ban.filter         [1518]: INFO    [geologger] Found 193.56.28.0/24 - 2020-12-18 14:41:20
2020-12-18 14:41:21,050 fail2ban.actions        [1518]: WARNING [geologger] 193.56.28.0/24 already banned

fail2ban debug:

['add', 'geologger', 'auto']
['multi-set', 'geologger', 'addfailregex', ['\\sgeo\\s+.* cidrs=\\([\\d\\./]+:<F-ID>[\\d\\./]+</F-ID>-.* ehlo=1 auth=0/1 rset=1 quit=1 commands=3/4$', '\\sgeo\\s+.* cidrs=\\([\\d\\./]+:<F-ID>[\\d\\./]+</F-ID>-.* ehlo=1 auth=0/1 quit=1 commands=2/3$', '\\sgeo\\s+[^\\(]+\\([^\\)]+?:dch\\) cidrs=\\([\\d\\./]+:<F-ID>[\\d\\./]+</F-ID>-.*?: Invalid user .*? port \\d+$', '\\sgeo\\s+.*:\\) cidrs=\\([\\d\\./]+:<F-ID>[\\d\\./]+</F-ID>-[\\d\\./]+\\) 1 0:.*?: Invalid user .*? port \\d+$', '\\sgeo\\s+.*:\\) cidrs=\\(<F-ID>[\\d\\./]+</F-ID>:[\\d\\./]+-[\\d\\./]+\\) 0 .*?: Invalid user .*? port \\d+$', '\\sgeo\\s+.*:\\) cidrs=\\([\\d\\./]+:[\\d\\./]+-<F-ID>[\\d\\./]+</F-ID>\\) 1 1:.*?: Invalid user .*? port \\d+$', '\\sgeo\\s+.* cidrs=\\([\\d\\./]+:[\\d\\./]+-<F-ID>[\\d\\./]+</F-ID>\\) 1 1: .* pam_unix\\(sshd:auth\\): authentication failure;', '\\sgeo\\s+.* cidrs=\\([\\d\\./]+:<F-ID>[\\d\\./]+</F-ID>-[\\d\\./]+\\) 1 0:.* pam_unix\\(sshd:auth\\): authentication failure;', '\\sgeo\\s+.* cidrs=\\(<F-ID>[\\d\\./]+</F-ID>:[\\d\\./]+-[\\d\\./]+\\) 0 .* pam_unix\\(sshd:auth\\): authentication failure;']]
['set', 'geologger', 'datepattern', '{^LN-BEG}']
['set', 'geologger', 'addlogpath', '/var/log/geologger.log', 'head']
['set', 'geologger', 'logencoding', 'auto']
['set', 'geologger', 'maxretry', 1]
['set', 'geologger', 'findtime', '30m']
['set', 'geologger', 'bantime', '1h']
['set', 'geologger', 'usedns', 'raw']
['set', 'geologger', 'ignorecommand', '']
['set', 'geologger', 'addaction', 'iptables-multiport']
['multi-set', 'geologger', 'action', 'iptables-multiport', [['actionstart', '<iptables> -N f2b-geologger\n<iptables> -A f2b-geologger -j RETURN\n<iptables> -I INPUT -p tcp -m multiport --dports ssh,2999,smtp,465,submission -j f2b-geologger'], ['actionstop', '<iptables> -D INPUT -p tcp -m multiport --dports ssh,2999,smtp,465,submission -j f2b-geologger\n<iptables> -F f2b-geologger\n<iptables> -X f2b-geologger'], ['actionflush', '<iptables> -F f2b-geologger'], ['actioncheck', "<iptables> -n -L INPUT | grep -q 'f2b-geologger[ \\t]'"], ['actionban', '<iptables> -I f2b-geologger 1 -s <ip> -j <blocktype>'], ['actionunban', '<iptables> -D f2b-geologger -s <ip> -j <blocktype>'], ['name', 'geologger'], ['bantime', '1h'], ['port', 'ssh,2999,smtp,465,submission'], ['protocol', 'tcp'], ['chain', '<known/chain>'], ['actname', 'iptables-multiport'], ['blocktype', 'REJECT --reject-with icmp-port-unreachable'], ['returntype', 'RETURN'], ['lockingopt', '-w'], ['iptables', 'iptables <lockingopt>'], ['blocktype?family=inet6', 'REJECT --reject-with icmp6-port-unreachable'], ['iptables?family=inet6', 'ip6tables <lockingopt>']]]
['start', 'geologger']

iptables:

There is no f2b-geologger in INPUT not "Chain f2b-geologger."

[sebres]

So now iptables -w -n -L INPUT | grep -q 'f2b-geologger[ \t]'; echo $? returns 1.
There is no f2b-geologger in INPUT not "Chain f2b-geologger."

Sure, fail2bans starts actions on demand (so by first ban only). So directly after start it may be indeed not there.
But you did provided the iptables output in issue description, and I see pretty well the chain f2b-geologger there.

can only concatenate str (not "NoneType") to str.

OK, I think I know what it could be:

The info from ticket looks like {'ip': '193.56.28.0/24', 'family': None ......
So for some reason family is None there, but it must be inet4:

$ python -c 'from fail2ban.server.actions import Actions; from fail2ban.server.ticket import BanTicket; a = Actions.ActionInfo(BanTicket("192.0.2.1/24")); print(a["family"]);'
inet4

I don't know why you use F-ID tags in your regex (<F-ID>[\d\./]+</F-ID>) exactly, but together with IP related banning action (which needs family to differentiate ipv4 and ipv6) it is a bit unfavorable - <F-ID> never resulting to an IP (it is raw string), so doesn't contain properties like family, etc.
#2560 implementing new tags for subnet/cidr which would cause correct ID wrapping like <SUBNET>, but it is released firstly with 0.10.5, so not available in your 0.10.2.
But unless upgrade, you can try to use tags <F-IP4>...</F-IP4> and <F-IP6>...</F-IP6>, so a custom RE:

subnet_ = (?:(?:::f{4,6}:)?<F-IP4>(?:\d{1,3}\.){3}\d{1,3}/\d+</F-IP4>|<F-IP6>(?:[0-9a-fA-F]{1,4}::?|::){1,7}(?:[0-9a-fA-F]{1,4}|(?<=:):)/\d+</F-IP6>)
failregex = ^... <subnet_> ...

PoC:

fail2ban-regex -v "$(date +%s) 192.0.2.1/24" '^\s+(?:(?:::f{4,6}:)?<F-IP4>(?:\d{1,3}\.){3}\d{1,3}/\d+</F-IP4>|<F-IP6>(?:[0-9a-fA-F]{1,4}::?|::){1,7}(?:[0-9a-fA-F]{1,4}|(?<=:):)/\d+</F-IP6>)'

Running tests
=============

Use   failregex line : ^\s+(?:(?:::f{4,6}:)?<F-IP4>(?:\d{1,3}\.){3}\d{1,3...
Use      single line : 1608309464 192.0.2.1/24


Results
=======

Failregex: 1 total
|-  #) [# of hits] regular expression
|   1) [1] ^\s+(?:(?:::f{4,6}:)?<F-IP4>(?:\d{1,3}\.){3}\d{1,3}/\d+</F-IP4>|<F-IP6>(?:[0-9a-fA-F]{1,4}::?|::){1,7}(?:[0-9a-fA-F]{1,4}|(?<=:):)/\d+</F-IP6>)
|      192.0.2.1/24  Fri Dec 18 17:37:44 2020
`-

Ignoreregex: 0 total

Date template hits:
|- [# of hits] date format
|  [1] {^LN-BEG}Epoch
|  ...
`-

Lines: 1 lines, 0 ignored, 1 matched, 0 missed
[processed in 0.01 sec]

[sebres]

Just for the record, I verified this issue against latest 0.10/0.11 - it looks more safe (does not cause this error can only concatenate str (not "NoneType") to str in command interpolation), because seems to stringify None in family, just it is anyway a wrong strategy together with IP-based actions, because using <F-ID> tags the action would not distinguish IPv6 and will call commands unconditionally (without special handling for IPv6).
As already said, tags <F-ID> is being considered for raw strings IDs usage rather.

[ValeryKV]

I used <F-ID> because you advised to use it #2866. And everything works since. Now I replaced F-ID to F-IP4, backed up sqlite db again and restarted fail2ban. In few minutes, I received the same error:

2020-12-19 09:56:02,616 fail2ban.actions        [4202]: NOTICE  [geologger] Ban 212.70.149.0/24
2020-12-19 09:56:02,616 fail2ban.actions        [4202]: ERROR   Failed to execute ban jail 'geologger' action 'iptables-multiport' info 'ActionInfo({'ip': '212.70.149.0/24', 'family': None, 'ip-rev': '', 'ip-host': None, 'fid': '212.70.149.0/24', 'failures': 5,
...
: can only concatenate str (not "NoneType") to str

I think it is better to upgrade to 0.11. Please advice the best way to upgrade from 0.10.2 to the latest version.

[sebres]

I used <F-ID> because you advised to use it #2866.

I'm sorry, I did not know about such issue (and as already said it was also not reproducible on my side).

I received the same error...

Huh... I would say it is impossible, tested with 0.10.2 now with my regex from above (F-IP4|F-IP6), and family is correct there, IP/CIDR gets banned with iptables-multiport and no error happens.
Can you probably run fail2ban temporary with DEBUG log-level? It should also provide a stack trace in error case.
I would really like to know where exactly this error occurs (to ensure it is not some unfavorable constellation, occurring regardless used fail2ban version).

I think it is better to upgrade to 0.11. Please advice the best way to upgrade from 0.10.2 to the latest version.

Well, basically you don't need install fail2ban for the test attempts or to try some new functionality, so firstly read How to test newer fail2ban version resp. use fail2ban standalone instance.

As for the upgrade, the newest upstream releases contain a debian package now, which can be installed manually, or one can install it from source.
See wiki :: How to install or upgrade fail2ban manually for details about both installation variants.

[ValeryKV]

I started fail2ban in debug mode. Here are the files. I did not find stack trace.

console.log
fail2ban.log

[ValeryKV]

BTW. The link https://github.com/fail2ban/fail2ban/issues/How-to-test-newer-fail2ban-version-resp.-use-fail2ban-standalone-instance to "How to test newer fail2ban version resp. use fail2ban standalone instance" returns "406 Not Acceptable." Most possible the issue is in the dot (-resp.-).

[ValeryKV]

I upgraded to 0.10.6 and my version with F-ID works. Now I will change the filter to use SUBNET. If you find nothing in attached log files, we can stop.

[sebres]

I started fail2ban in debug mode. Here are the files. I did not find stack trace.

Well, console.log shows debug messages, but it does not contain the error (so no call stack then)... fail2ban.log contains the error, but it does not contain any debug message. You seems to start fail2ban-client in verbose mode (-v), I told about log-level of server (either you provide it via command line with --loglevel DEBUG or via configuration in /etc/fail2ban.local).

The link returns "406 Not Acceptable." Most possible the issue is in the dot

No, my bad (used relative link)... Updated.

I upgraded to 0.10.6 and my version with F-ID works.

Glad it works, so we can exclude that it was some constellation affecting your system only, but just old version.