Bug 590783

Event posted on 04-15-2010 10:07am EDT by kolotov

Description of problem:

Racoon daemon stops responding for ~2 minutes. 
At this time it is not responding to DPD from far end
(just nothing in logs at all like it fall to forever
loop or waiting in sys call, etc...).

How reproducible: Always reproducible under traffic

Steps to Reproduce:

Set IKE phase 1 lifetime to 10 minutes and phase 2 lifetime 
to 3 minutes (problem can be duped with any lifetimes, small 
one is just make it easy) for near end and far end.

It was reproduced during testing of high call traffic between
telephony servers.

Actual results:

As described.

Expected results:

Racoon should not die or stuck for some time.

Additional info:

Attached:
1. sos report files
2. racoon debug logs from this server, issue time in log is 20:17
This event sent from IssueTracker by vincew  [SEG - Base OS]
 issue 767803

Event posted on 04-26-2010 06:57am EDT by kolotov

In addition to previous note, it seems that there are 2 cases when handling
isakmp delete payload (I'm referring to base_others.log, Apr 21 test):

Code flow:

session
  select(...)
  admin_handler
  ...
  isakmp_handler
    isakmp_main
      isakmp_info_recv
        isakmp_info_recv_d
          purge_ipsec_spi
            pfkey_dump_sadb
              pfkey_send_dump
              ...
              while(1)
                pk_recv(pfkey_socket)
          ...
          if (spi in packet is same as spi in db)
            pfkey_send_delete          
  ...
  pfkey_handler
    pk_recv(pfkey_socket)
      recv                                      <--- we stuck here
      
1. Good case:

Apr 21 12:50:08 altnrs racoon: DEBUG: seen nptype=8(hash)
Apr 21 12:50:08 altnrs racoon: DEBUG: seen nptype=12(delete)
Apr 21 12:50:08 altnrs racoon: DEBUG: succeed.
Apr 21 12:50:08 altnrs racoon: DEBUG: call pfkey_send_dump
Apr 21 12:50:08 altnrs racoon: DEBUG: check spi(packet)=1576530486
spi(db)=4010845127.
Apr 21 12:50:08 altnrs racoon: DEBUG: check spi(packet)=1576530486
spi(db)=1576530486.
Apr 21 12:50:08 altnrs racoon: DEBUG: an undead schedule has been
deleted.
Apr 21 12:50:08 altnrs racoon: INFO: purged IPsec-SA proto_id=ESP
spi=1576530486.
Apr 21 12:50:08 altnrs racoon: DEBUG: purged SAs.
Apr 21 12:50:08 altnrs racoon: DEBUG: get pfkey DELETE message

In good case, SPI is found in db and pfkey delete message is sent to
pfkey_socket, no gaps.

2. Bad case:

Apr 21 12:35:20 altnrs racoon: DEBUG: seen nptype=8(hash)
Apr 21 12:35:20 altnrs racoon: DEBUG: seen nptype=12(delete)
Apr 21 12:35:20 altnrs racoon: DEBUG: succeed.
Apr 21 12:35:20 altnrs racoon: DEBUG: Cannot record event: event queue
overflowed
Apr 21 12:35:20 altnrs racoon: DEBUG: call pfkey_send_dump
Apr 21 12:35:20 altnrs racoon: DEBUG: check spi(packet)=3445397493
spi(db)=2058958942.
Apr 21 12:35:20 altnrs racoon: DEBUG: purged SAs.

<gap, 2 minutes>

Apr 21 12:37:42 altnrs racoon: DEBUG: get pfkey ACQUIRE message

In bad case, spi is not found in db. So we drain all data from
pfkey_socket in pfkey_dump_sadb() in while(1) loop. When we leave this
function pfkey_socket contains no data. But after that we immediately go
to pfkey_handler and trying to get data from it. Since it contains nothing
and no timeout is set - we wait forever until ANY message comes to us (for
instance ACQUIRE like in logs above).

Difference against good case is that in good case pfkey delete message is
put to socket, so when we try recv() inside pfkey_handler(), we have data
to receive. 

Problem here is that pfkey_handler() seems to be written basing on
assuption that it is called after select(), we sure that there is some
data in the socket, so we make blocking sys call recv() to get this data.
Btw, gdb backtrace also shows that there is 0 bytes in socket
(sadb_msg_len = 0):

#0  0x00560f2c in recv () from /lib/libc.so.6
No symbol table info available.
#1  0x00b4b19e in pk_recv (so=5, lenp=0xba7ff4) at pfkey.c:3032
       buf = {sadb_msg_version = 10 '\n', sadb_msg_type = 125 '}',
sadb_msg_errno = 254 '?', sadb_msg_satype = 11 '\v', sadb_msg_len =
0, 
  sadb_msg_reserved = 0, sadb_msg_seq = 0, sadb_msg_pid = 152615312}



Could you please provide your view on this? 


This event sent from IssueTracker by vincew  [SEG - Base OS]
 issue 767803

Event posted on 04-29-2010 06:20am EDT by kolotov

I don't think it is correct to say that FD_ISSET will return true only if
there is data in socket. This macros is just checking that specified fd is
in fd_set and it's status is ready to recieve, all this is set inside
select() (something like that).

Only select() call gives answer if there is some data in socket or not. 

Review my analysis one more time, issue happens like:
1. select() called from session() determines that there is data to receive
in admin socket, isakmp socket and pfkey socket
2. handlers are called in turn from session()
3. isakmp_handler() reads data from isakmp socket, handles request. If
this is request to delete spi, pfkey sadb dump request is sent to kernel
to get list of spi's we have. This list is put by kernel to
***pkfey_socket***. After that we read all data from pfkey_socket. If no
such spi in the list, we just return back to session()
4. pfkey_handler() called immediately after that from session(). FD_ISSET
check can't help at all, because fd_set structure was updated by select()
only before isakmp_handler(). And it is not updated after isakmp_handler()
drain all data from pfkey_socket.
5. pfkey_handler() calls pk_recv() and waits for any message to
pfkey_socket forever.

Hope this is now clear enough.


This event sent from IssueTracker by vincew  [SEG - Base OS]
 issue 767803

Event posted on 04-30-2010 07:43am EDT by kolotov

I've already tried calling pfkey_handler() before isakmp_handler() - and
this fixes issue with racoon hang, I didn't find any delays in logs. This
looks much better than setting timeout for socket.

But you are right saying that isakmp_handler() ideally shouldn't touch
pfkey_socket at all, because if both sockets has data in them after
select(), isakmp_handler() can get not only sadb dump from pfkey_socket,
but other important messages. This can be potential cause of data
corruption. 

I have one more question, about how racoon should act if it receives
notification from far end to delete old phase1 sa? This is handled in
purge_remote(). Currently racoon is deleting old phase 1 sa and also all
associated phase 2 sa's. I'm wondering to know if this is expected
behavior. I.e. why not leaving phase 2 sa's, kernel will remove them ones
they expire...

Can you provide any advice on this?

Thanks.


This event sent from IssueTracker by vincew  [SEG - Base OS]
 issue 767803

Event posted on 05-04-2010 10:49am EDT by vincew

Posting Tomas' email reply so we have it in the ticket:
------------------------------
On Mon, 2010-05-03 at 16:43 -0400, Vince Worthington wrote: 
> > Hi Tomas,
> > 
> > Scott Mayhew had an idea about that racoon issue we chatted about last

> > week.  The one where isakmp_handler was draining the pfkey socket that

> > leads to a blocking recv() call because select() is not getting called

> > again before the FD_ISSET() check for pfkey_handler.
> > 
> > (Also, switching the order of isakmp_handler and pfkey_handler
FD_ISSET 
> > checks like you suggested does seem to work OK also).
> > 
> > Scott's idea was, why don't we just do a non-blocking, "peek"
receive 
> > (ie, recv() with MSG_DONTWAIT|MSG_PEEK flags) on the pfkey socket and

> > test for a positive number of bytes returned, before we do FD_ISSET 
> > again and call pfkey_handler?  ie, see if there is still anything to 
> > receive on the socket before we call pfkey_handler and end up with a 
> > blocking recv() when the socket is drained?
> > 
> > I looked at the code doing recv* calls in the handler function chains

> > and they appear to make liberal use of MSG_PEEK's also, so it
doesn't 
> > seem to really go against how it is coded elsewhere - except that with

> > MSG_DONTWAIT we can find out whether a non-peek recv would block or
not 
> > (no data waiting) and avoid calling pfkey_handler at all.
> > 
> > I put a patch together and am wondering what your opinion of it would

> > be.  We've done some basic testing and it appears to work OK, but we

> > have still not heard back from the customer who we believe is also 
> > testing it.

This is really questionable. The main problem is that if the order of
the isakmp_handler and pfkey_handler is as is currently the race that
causes the blocking recv() causes also some events from pfkey to be
lost. Switching the order of the calls might help in this case although
it does not eliminate the race completely, it just makes it much less
likely to appear and the outcome of the race should never be the
blocking recv(), only some event can be lost.

I would really like to see how would long testing of this solution
worked out.

-- Tomas Mraz
No matter how far down the wrong road you've gone, turn back. Turkish
proverb 
------------------------------


This event sent from IssueTracker by vincew  [SEG - Base OS]
 issue 767803

Event posted on 05-06-2010 01:23pm EDT by vincew

vw7 build:

http://brewweb.devel.redhat.com/brew/taskinfo?taskID=2425875

vw7 build has noopt compile + patch attached

As Tomas mentioned, we *should* be able to test whether the change this
upstream-like patch helps the problem.  They (best I can tell) appear to
NOT be using privilege separation (ie they are running racoon as root) so
it should be OK to call pfkey_sock instead as this patch does.

If this helps them, it is probably going to mean we have more patching to
do but at least it will tell us we are moving in the right direction.

Also for the sake of getting this documented in the case, this the
upstream patch Tomas recommended:

http://cvsweb.netbsd.org/bsdweb.cgi/src/crypto/dist/ipsec-tools/src/racoon/pfkey.c.diff?r1=1.38&r2=1.39

although 0.6.5 doesn't have a privsep_socket() function, so further
patchwork may be required.

Thanks,
Vince


This event sent from IssueTracker by vincew  [SEG - Base OS]
 issue 767803

(In reply to comment #4)
> Event posted on 04-30-2010 07:43am EDT by kolotov

> I have one more question, about how racoon should act if it receives
> notification from far end to delete old phase1 sa? This is handled in
> purge_remote(). Currently racoon is deleting old phase 1 sa and also all
> associated phase 2 sa's. I'm wondering to know if this is expected
> behavior. I.e. why not leaving phase 2 sa's, kernel will remove them ones
> they expire...
> 
> Can you provide any advice on this?

The removing of SA on notification from far end might be changed in upstream CVS in a way similar to what is suggested here. But I am slightly afraid of changing this as it might in some circumstances mean that the phase 2 SA data would not be properly deleted in racoon daemon and this would result in a memory leak.

Created attachment 418794 [details]
patch customer reports success with (uses pfkey_open instead of privsep_socket since it is not present in 0.6.5)

Event posted on 06-02-2010 10:35am EDT by vincew

Scott if you wouldn't mind, can you file an accelerated fix request for
this case?  Here's (I think) our most current process doc on it:

http://intranet.corp.redhat.com/ic/intranet/HotFix

If you would, flip this back to WoSEG once the request is filed and I'll
escalate it to SEG TL so Jeremy can engage ENG on it.

PS:  Note that while customer has verified the concept patch we still need
the privsep_socket function the actual upstream patch uses.

Thanks
Vince

Internal Status set to 'Waiting on Support'

This event sent from IssueTracker by vincew 
 issue 767803

*** Bug 599071 has been marked as a duplicate of this bug. ***

Feedback from customer was positive.

Also, for future reference purposes, this was the gdb backtrace:

(gdb) bt
#0  0x00560f2c in recv () from /lib/libc.so.6
#1  0x00b4b19e in pk_recv (so=5, lenp=0xba7ff4) at pfkey.c:3032
#2  0x00b4b691 in pfkey_handler () at pfkey.c:204
#3  0x00b2a6a2 in session () at session.c:215
#4  0x00b2995e in main (ac=5, av=0xbfb9b02c) at main.c:253

(we've since had a similar case raised by another customer who believed it might be the same bug but the backtrace was different)

--vince

is there any update to this?  this bug bites me on a regular basis.

(In reply to comment #26)
> is there any update to this?  this bug bites me on a regular basis.

What ipsec-tools rpm package version do you have?

my version ipsec-tools-0.6.5-14.el5_5.5

Then this is a different bug as the version you have uses a separate socket for the pfkey sadb dumps.

Please use the regular support channels http://www.redhat.com/support to report the issue. Thank you.