Bug 191343 - [ipnat] ipnat error at boot disables active sessions
Summary: [ipnat] ipnat error at boot disables active sessions
Status: In Progress
Alias: None
Product: Base System
Classification: Unclassified
Component: kern (show other bugs)
Version: 10.0-STABLE
Hardware: Any Any
: --- Affects Only Me
Assignee: Cy Schubert
URL:
Keywords:
Depends on:
Blocks: 235110
  Show dependency treegraph
 
Reported: 2014-06-24 14:45 UTC by David.Boyd49
Modified: 2019-02-09 18:12 UTC (History)
1 user (show)

See Also:


Attachments
/var/log/message with ipnat failure (215.86 KB, text/plain)
2014-07-01 23:01 UTC, David.Boyd49
no flags Details
Test (364 bytes, patch)
2016-03-09 02:59 UTC, Cy Schubert
no flags Details | Diff
ipfs dtrace diff (681 bytes, patch)
2019-02-02 23:08 UTC, Cy Schubert
no flags Details | Diff
/etc/ipf.rules, /etc/ipnat.rules, ipnat -lv, ping (3.51 KB, text/plain)
2019-02-04 17:53 UTC, David.Boyd49
no flags Details
ipnat -lv, ping (1002 bytes, text/plain)
2019-02-04 17:54 UTC, David.Boyd49
no flags Details
A shot in the dark. (3.17 KB, patch)
2019-02-04 20:29 UTC, Cy Schubert
no flags Details | Diff
Print debugging information (503 bytes, patch)
2019-02-06 05:13 UTC, Cy Schubert
no flags Details | Diff
dmesg output with 10 lines of context (938 bytes, text/plain)
2019-02-06 19:14 UTC, David.Boyd49
no flags Details
Probable fix (772 bytes, patch)
2019-02-07 01:27 UTC, Cy Schubert
no flags Details | Diff
Dump output after patch was applied (80.62 KB, text/plain)
2019-02-07 18:44 UTC, David.Boyd49
no flags Details
script capture of debug session (12.99 KB, text/plain)
2019-02-07 22:47 UTC, David.Boyd49
no flags Details
script capture of debug session (2) (21.55 KB, text/plain)
2019-02-08 15:24 UTC, David.Boyd49
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description David.Boyd49 2014-06-24 14:45:19 UTC
Customer upgraded 2 test systems to release/10.0.0 and then to releng/10.0 (10.0-RELEASE-p5).  With same ipnat configuration as used in 9.2-RELEASE, ipnat didn't create active sessions. Customer then rebooted system and ipnat functionality returned.  A subsequent reboot disabled ipnat again.

Customer reported this problem to me. Skeptically, I agreed to visit site.

The console log for the failing ipnat reports an error at boot:

IP Filter: v5.1.2 initialized, default = pass all, logging = enabled
Enabling ipfilter
Installing NAT rules.
0 entries flushed from NAT table
0 entries flushed from NAT list
in=0x801406600:SIOCSTPUT:no such process

Now the weird part:

On reboot (shutdown -r now) the SIOCSTPUT error is not reported and ipnat works.

On reboot (shutdown -r now) the SIOCSTPUT error returns and ipnat fails.

After a hard reset or power off/power on the SIOCSTPUT error "always" returns and ipnat fails (20+ attempts) and then the every other reboot cycle begins again (50+ attempts).

Hardware is Supermicro PDSME+ motherboard with quad-core Intel Xeon (2.66 Ghz) and 4 GB memory

I have verified the kernel configuration is simply

include GENERIC
ident SUPERMICRO

I rebuilt customer's system with stable/10 as of 06/20/2014 ... no change.

I have /etc/ipf.rules, /etc/ipnat.rules, /etc/rc.conf, kernel config files in my possession.

I also have acquired one of the test machines so patching, rebuilding and testing are possible.
Comment 1 David.Boyd49 2014-06-24 15:26:59 UTC
I have tried to reproduce the customer's report concerning hard booting.  I don't find that it makes any difference whether the reboot is hard or soft.

I wonder if this problem is related to ipfs and state tables?
Comment 2 David.Boyd49 2014-06-24 16:10:09 UTC
Customer has verified that her testing methodology for hard reboots was flawed.

I have disabled ipnat state save by adding ipfs_flags="-Sv" to /etc/rc.conf.

I have rebooted several times without the error being reported.

This is only a workaround ... customer requires ipnat state save/restore for production systems.
Comment 3 Mark Linimon freebsd_committer freebsd_triage 2014-06-26 01:36:00 UTC
Over to maintainers.
Comment 4 Cy Schubert freebsd_committer 2014-06-30 19:58:02 UTC
Can you please get a copy of the logs from when it fails?
Comment 5 David.Boyd49 2014-07-01 23:01:56 UTC
Created attachment 144327 [details]
/var/log/message with ipnat failure

Attachment is /var/log/messages with ipnat failure.

System was booted with verbose option.
Comment 6 David.Boyd49 2016-03-08 00:28:29 UTC
This problem persists into 10.3-RC1.

The workaround was quite clumsy and has been updated to simple disable ipfs (ipfs_enable="NO") in /etc/rc.conf(.local).
Comment 7 Cy Schubert freebsd_committer 2016-03-09 02:59:27 UTC
Created attachment 167888 [details]
Test

I have a hunch that ipfs tries to load state before ipfilter is ready to receive it. can you try the attached patch?

This is not a permanent solution but will point to a solution.
Comment 8 Cy Schubert freebsd_committer 2016-04-20 02:40:53 UTC
Can post or send me copies of your rules? Do you use keep-frags?
Comment 9 Eitan Adler freebsd_committer freebsd_triage 2018-05-28 19:49:46 UTC
batch change:

For bugs that match the following
-  Status Is In progress 
AND
- Untouched since 2018-01-01.
AND
- Affects Base System OR Documentation

DO:

Reset to open status.


Note:
I did a quick pass but if you are getting this email it might be worthwhile to double check to see if this bug ought to be closed.
Comment 10 Cy Schubert freebsd_committer 2018-05-29 01:24:48 UTC
Feedback timeout.
Comment 11 David.Boyd49 2019-01-31 16:17:06 UTC
Sorry for not responding sooner.

I have applied the suggested change to /etc/rc.d/ipfs to 11.2-RELEASE-p8, 11.2-STABLE, 12.0-RELEASE-p2, 12.0-STABLE and 13.0-CURRENT but the problem persists.

When ipfs is enabled in 13.0-CURRENT the error message changes somewhat:

in=0x800693000: SIOCSTPUT: Cannot allocate memory
                           ----------------------

I can test any change/fix on bare meta or VirtualBox VM's.

Thanks.

David
Comment 12 Cy Schubert freebsd_committer 2019-01-31 20:51:37 UTC
How many NAT rules do you have? How big are your nat tables?

ipnat -lv (just before a reboot)

ls -l /var/db/ipf

On the 13-CURRENT system only (we'll work on this first and work on the other problem later), can you run the following dtrace script in the background?

dtrace -o /tmp/dtrace.out -n 'sdt:::user_error { printf("%d\n", arg0); stack(); }' &

Post /tmp/dtrace.out.

This must be running prior to ipfs, so you might want to alter /etc/rc.d/ipfs to start the dtrace before ipfs (the program) runs. Then reboot.
Comment 13 Cy Schubert freebsd_committer 2019-02-02 05:16:31 UTC
ping.

I am not able to reproduce this problem. Without any more information I must conclude this is a site misconfiguration.
Comment 14 David.Boyd49 2019-02-02 12:34:02 UTC
I can reproduce this problem with no effort whatsoever ... a GENERIC system with two or more network interfaces, an "open" firewall and a very simple NAT configuration.

When the system boots initially, the SIOCSTPUT error doesn't occur, and a simple ping statement

            ping -S 172.23.161.1 freebsd.org

is successful.

Upon reboot (shutdown -r now), the SIOCSTPUT error is displayed and the above ping statement fails to exit the system.

I have tried to place the suggested dtrace statement into /etc/rc.d/ipfs but I'm not sure that I am doing it correctly ... the only output that I see are NL's.

I will have some time tomorrow and the next day to continue testing.  I can easily make all configurations available  I have everything  at bare minimum.

I have access to one production 12.0-RELEASE system with six network interfaces, a full (working) firewall and about eight NAT rules.

I have access to one test system with multiple network interfaces and open firewall and minimal NAT rules.

I have access to five (or more) VirtualBox VM's with two or three network interfaces each, open firewall rules and minimal NAT rules.

I really hope that we can continue to work on this.

Thanks.

David.
Comment 15 Cy Schubert freebsd_committer 2019-02-02 15:10:31 UTC
The dtrace script prints out the error code and a stack trace. Without it the information given in this PR all we can do is wildly guess.

I understand all the systems in question are virtualbox VMs. How much memory have you given each VM? Are they i386 or amd64? Does it fail like this on a physical box?

From here on out I will do my best to guess wildly but if you want this fixed I need more information. The dtrace output would help a lot.
Comment 16 David.Boyd49 2019-02-02 19:46:00 UTC
(In reply to Cy Schubert from comment #15)

All of the test systems are VM's. Each is  configured with 2 cpus amd64 4gb memory

The original systems that exhibited this problem were all physical.

I have access to two physical systems. One is a test machine that is available for any kind of testing.  The other is a production system, but I can modify config files and conduct testing in the evenings.

The suggestion that this is a site misconfiguration is intriguing.  That could make  a solution easy if the misconfiguration could be identified.  I don't have any problem with that solution.

I don't know why dtrace isn't producing output ... can you suggest a line number in  /etc/rc.d/ipfs where the one-liner should be placed?

I'm not expecting a miracle ... I understand that without physical evidence, this problem could go unsolved (forever).

I will supply /etc/ipf.rules, /etc/ipnat.rules, /etc/rc.conf.local, dmesg output, ipnat -lv, ls -l /var/db/ipf (this directory is usually empty, but occasionally shows 2 state files) tomorrow.

The most intriguing part of this is that the NAT failure(s) only occur on every other boot of the system(s).

Cy, thanks for your assistance in this matter.

David.
Comment 17 Cy Schubert freebsd_committer 2019-02-02 23:08:36 UTC
Created attachment 201662 [details]
ipfs dtrace diff

Apply this, rm /var/db/dtrace.out, then reboot again. Post dtrace.out.
Comment 18 David.Boyd49 2019-02-04 16:06:42 UTC
There is still no usable output from dtrace ... just two line feeds.

dmesg -a output shows: dtrace: description 'sdt:::user error ' matched 1 probe

I have been collecting the ipnat.ipf and ipstate.ipf files.

The error occurs, on startup, when the length of these files is greater than zero (several thousand bytes).

Because there are no NAT entries (I assume) the subsequent shutdown writes files of zero bytes.

On startup, no error is presented.

With nothing saved, no NAT entries are restored.

This is the sequence on alternating boots.

I wish I had something to offer, but I don't.

Thanks for your efforts.

Let me know what to do next.

David.
Comment 19 David.Boyd49 2019-02-04 16:27:31 UTC
Cy,

Please feel free to suggest any configuration changes that you think might have an affect on this problem.  There is enough hardware (real and virtual) available to load and reload any version of the FreeBSD software.  I have tried not to make many/any changes to system configuration files.  I never to get testy about suggestions that may expose a long-standing problem.

Please have at it.

David
Comment 20 David.Boyd49 2019-02-04 17:53:43 UTC
Created attachment 201726 [details]
/etc/ipf.rules, /etc/ipnat.rules, ipnat -lv, ping
Comment 21 David.Boyd49 2019-02-04 17:54:13 UTC
Created attachment 201727 [details]
ipnat -lv, ping
Comment 22 Cy Schubert freebsd_committer 2019-02-04 20:29:01 UTC
Created attachment 201730 [details]
A shot in the dark.

(In reply to David.Boyd49 from comment #18)

With no information this is difficult. I'll take a wild guess then. There might be some configuration issues with your systems in general that might be causing this issue. DTrace should also produce an integer output that will tell me where the error is.

Your kernel might be running out of memory and when ip_nat is requesting memory from the kernel through KMALLOC it is denied because no memory is available. 

Doubling the kernel memory might help or you can try the attached patch. No guarantees as I have no information to go on.

Try the attached patch. Rather than issue a malloc(9) with no wait, this malloc(9) waits for memory to come available. This may hang your system at boot though.
Comment 23 David.Boyd49 2019-02-05 18:26:08 UTC
As you guessed,  the patch caused the system to hang on boot.  I have disabled ipfs for now.

I am going to try to determine which configuation change occurred between 9.x-RELEASE and 10.0-RELEASE that that may have triggered this issue.

Please give me through the coming weekend to complete my investigation.

In the mean time, if you have something else you would like me to try, just let me know.

Thanks.

David
Comment 24 Cy Schubert freebsd_committer 2019-02-05 20:31:46 UTC
This proves it. Your kernel is running out of memory and is unable to satisfy ipfilter's request for more. Specifying wait causes it to hang.

In the mean time I'll create a patch to cause your kernel to panic when it gets the error, capturing a dump.
Comment 25 David.Boyd49 2019-02-05 22:43:15 UTC
Cy,

Progress report:

I loaded systems with 9-3-RELEASE and 10.1-RELEASE. Both systems were configured with 8gb memory (instead of 4gb).

/etc/rc.conf on both is:

hostname="freebsd"
ipfilter_enable="YES"
ipfs_enable="YES"
ipmon_enable="YES"
ipnat_enable="YES"

ifconfig_vtnet0="DHCP"
ifconfig_vtnet1="inet 172.23.161.1/24"

synchronous_dhclient="YES"

gateway_enable="YES"

default_router="NO"

/etc/ipnat.rules on both is:

map vtnet0 172.23.161.0/24 -> 0.0.0.0/32 portmap tcp/udp auto
map vtnet0 172.23.161.0/24 -> 0.0.0.0/32

No problem is observed on 9.3-RELEASE.

When length of saved /var/db/ipf/ipnat.ipf is zero, ipnat starts normally.

When length is not zero, the dreaded error message is observerd and ipnat doesn't function after boot.

The length of /var/db/ipf/ipstate.ipf doesn't seem to matter.

This is the first time that I have noticed that IP Filter was upgraded between these releases.

I see that you worked on several ipfilter issues then.

I anxiously await your patch.

I really do appreciate the time and effort that you have put into solving this problem.

Thanks.

David
Comment 26 Cy Schubert freebsd_committer 2019-02-06 05:13:58 UTC
Created attachment 201783 [details]
Print debugging information

This patch doesn't fix anything. It prints out the size it's attempting to malloc.

After applying the patch. Boot. Then,

dmesg | grep 'ip_nat error 60038'

Post the output. I expect some uninitialized number.
Comment 27 David.Boyd49 2019-02-06 19:14:51 UTC
Created attachment 201798 [details]
dmesg output with 10 lines of context

Cy,

I hope this is what you were expecting.

Standing by.

David
Comment 28 Cy Schubert freebsd_committer 2019-02-06 19:58:13 UTC
As expected an uninitialized variable.
Comment 29 Cy Schubert freebsd_committer 2019-02-07 01:27:11 UTC
Created attachment 201806 [details]
Probable fix

This patch reverts the following from the ipfilter upline.

revision 1.57
date: 2009/05/01 18:37:30;  author: darren_r;  state: Exp;  lines: +6 -6
2785209 variable size NAT rules not handled well


Can you test this out, please?
Comment 30 David.Boyd49 2019-02-07 18:44:29 UTC
Created attachment 201821 [details]
Dump output after patch was applied

Cy,

Sorry!  The patch applied cleanly, but, on reboot, the system panicked.

Today, and tomorrow, are good for me for further testing.

Thanks.

David
Comment 31 Cy Schubert freebsd_committer 2019-02-07 20:51:10 UTC
uname -a please.

Are do you have the latest ipfilter commits?
Comment 32 Cy Schubert freebsd_committer 2019-02-07 20:57:08 UTC
nevermind. I see you do have them.
Comment 33 Cy Schubert freebsd_committer 2019-02-07 21:00:09 UTC
In the crash dump:

frame 18
p in
Comment 34 David.Boyd49 2019-02-07 22:47:00 UTC
Created attachment 201827 [details]
script capture of debug session

I realize this is more than you asked for, but I didn't want to leave anything out.
Comment 35 Cy Schubert freebsd_committer 2019-02-08 02:54:06 UTC
sorry, that should have been

p *in
Comment 36 David.Boyd49 2019-02-08 15:24:23 UTC
Created attachment 201842 [details]
script capture of debug session (2)

Cy,

Lots more output.

David
Comment 37 Cy Schubert freebsd_committer 2019-02-09 01:42:35 UTC
It's clear that many of the fields are uninitialized. This is also the issue I "fixed" in PR 235110 which I now believe the feature is incomplete and was most likely never tested when ipfilter 5.1.0 was released.

A complete assessment of the ipfs feature will be required. This will take some time.
Comment 38 David.Boyd49 2019-02-09 16:42:47 UTC
Cy,

I appreciate you attention to this problem.

Through 12.0-RELEASE we have disabled ipfs as a workaround.  We will continue to do this.  Just let me know when you are ready for more testing.  Perhaps this can be resolved during the 13.0-CURRENT cycle ... or not.  The stability of FreeBSD has made this issue less of a concern for the customer than it was four years ago.

Thanks, again.

David.
Comment 39 Cy Schubert freebsd_committer 2019-02-09 18:12:05 UTC
No problem. When Darren rewrote significant portions of ipfilter for 5, ipfs was missed and appears untested.