iked - pfkey_write: writev failed: Invalid argument (-current)

classic Classic list List threaded Threaded
6 messages Options
Reply | Threaded
Open this post in threaded view
|

iked - pfkey_write: writev failed: Invalid argument (-current)

Mark Patruck
Information about this error has already been sent to mpi@ and patrick@,
so this is just to make sure it don't get lost before the lock.

iked on -current still produces an error every few hours:

iked[29197]: pfkey_write: writev failed: Invalid argument


Details:
-------

- after mpi@s change 'Add per-TDB counters and a new SADB extension (1)'
iked showed the following errors:

'iked[12345]: pfkey_reply: no reply from PF_KEY'           (every minute)
'iked[12345]: pfkey_write: writev failed: Invalid argument (every few hours)

- a change by mpi@ (2) fixed the 'no reply from PF_KEY', but

'iked[12345]: pfkey_write: writev failed: Invalid argument (every few hours)

stays.


(1) https://marc.info/?l=openbsd-cvs&m=153546931106420&w=2
(2) https://marc.info/?l=openbsd-cvs&m=153675149127886&w=2

Thanks,

        -Mark

--
Mark Patruck ( mark at wrapped.cx )
GPG key 0xF2865E51 / 187F F6D3 EE04 1DCE 1C74  F644 0D3C F66F F286 5E51

http://www.wrapped.cx

Reply | Threaded
Open this post in threaded view
|

Re: iked - pfkey_write: writev failed: -> issue found

Mark Patruck
I've found the reason for the error message

iked[24455]: pfkey_write: writev failed: Invalid argument
iked[24455]: pfkey_write: writev failed: Invalid argument

that comes up when the Child SA expires. (this affects 6.4 and -current)

It appears when using a tap interface != default enc0 (for example enc5
in routing domain 5). So you can simply reproduce via

$ doas ifconfig enc1 create

use "tap enc1" in iked.conf     (hint: "tap enc0" works)

For testing purposes it makes sense to lower "lifetime" to f.e. 2m.


On Tue, Sep 25, 2018 at 10:50:43AM -0300, Martin Pieuchot wrote:
> On 24/09/18(Mon) 20:21, Mark Patruck wrote:
> > Hi Martin,
> >
> > if you need additional info or have a diff to test, drop me a
> > note.
>
> I don't have time to look at this, better send a report to bugs@, you
> could also poke patrick@ to see if he has some ideas.

--
Mark Patruck ( mark at wrapped.cx )
GPG key 0xF2865E51 / 187F F6D3 EE04 1DCE 1C74  F644 0D3C F66F F286 5E51

http://www.wrapped.cx

Reply | Threaded
Open this post in threaded view
|

Re: iked - pfkey_write: writev failed: -> issue found

David Hill-3
On Sat, Oct 27, 2018 at 05:35:16PM +0200, Mark Patruck wrote:

> I've found the reason for the error message
>
> iked[24455]: pfkey_write: writev failed: Invalid argument
> iked[24455]: pfkey_write: writev failed: Invalid argument
>
> that comes up when the Child SA expires. (this affects 6.4 and -current)
>
> It appears when using a tap interface != default enc0 (for example enc5
> in routing domain 5). So you can simply reproduce via
>
> $ doas ifconfig enc1 create
>
> use "tap enc1" in iked.conf     (hint: "tap enc0" works)
>
> For testing purposes it makes sense to lower "lifetime" to f.e. 2m.
>
>
> On Tue, Sep 25, 2018 at 10:50:43AM -0300, Martin Pieuchot wrote:
> > On 24/09/18(Mon) 20:21, Mark Patruck wrote:
> > > Hi Martin,
> > >
> > > if you need additional info or have a diff to test, drop me a
> > > note.
> >
> > I don't have time to look at this, better send a report to bugs@, you
> > could also poke patrick@ to see if he has some ideas.
>
> --
> Mark Patruck ( mark at wrapped.cx )
> GPG key 0xF2865E51 / 187F F6D3 EE04 1DCE 1C74  F644 0D3C F66F F286 5E51
>
> http://www.wrapped.cx
>

I hit this too.

in pfkey_sa, if the action is SADB_DELETE, the code skips (goto) ahead,
so sa_tap is left uninitialized.  I tried the following diff first,
thinking sa_tap wasn't being initialized in the SADB_DELETE case.  But
it didn't help.

Index: pfkey.c
===================================================================
RCS file: /cvs/src/sbin/iked/pfkey.c,v
retrieving revision 1.59
diff -u -p -r1.59 pfkey.c
--- pfkey.c 27 Nov 2017 18:39:35 -0000 1.59
+++ pfkey.c 25 Nov 2018 15:46:32 -0000
@@ -530,6 +530,13 @@ pfkey_sa(int sd, uint8_t satype, uint8_t
  bzero(&sa_ltime_hard, sizeof(sa_ltime_hard));
  bzero(&sa_ltime_soft, sizeof(sa_ltime_soft));
 
+ if (pol->pol_tap != 0) {
+ bzero(&sa_tap, sizeof(sa_tap));
+ sa_tap.sadb_x_tap_exttype = SADB_X_EXT_TAP;
+ sa_tap.sadb_x_tap_len = sizeof(sa_tap) / 8;
+ sa_tap.sadb_x_tap_unit = pol->pol_tap;
+ }
+
  if (action == SADB_DELETE)
  goto send;
 
@@ -641,13 +648,6 @@ pfkey_sa(int sd, uint8_t satype, uint8_t
  sa_tag.sadb_x_tag_taglen = strlen(tag) + 1;
  } else
  tag = NULL;
-
- if (pol->pol_tap != 0) {
- bzero(&sa_tap, sizeof(sa_tap));
- sa_tap.sadb_x_tap_exttype = SADB_X_EXT_TAP;
- sa_tap.sadb_x_tap_len = sizeof(sa_tap) / 8;
- sa_tap.sadb_x_tap_unit = pol->pol_tap;
- }
 
  send:
  iov_cnt = 0;


So, i reversed the logic and thought maybe SADB_DELETE doesn't want
sa_tap to be part of the iov and came up with this diff.  I no longer
get writev errors on rekey.  I am not sure if it is correct as-is
though.

Index: pfkey.c
===================================================================
RCS file: /cvs/src/sbin/iked/pfkey.c,v
retrieving revision 1.59
diff -u -p -r1.59 pfkey.c
--- pfkey.c 27 Nov 2017 18:39:35 -0000 1.59
+++ pfkey.c 25 Nov 2018 15:37:11 -0000
@@ -764,7 +764,7 @@ pfkey_sa(int sd, uint8_t satype, uint8_t
  iov_cnt++;
  }
 
- if (pol->pol_tap != 0) {
+ if (pol->pol_tap != 0 && action != SADB_DELETE) {
  /* enc(4) device tap unit */
  iov[iov_cnt].iov_base = &sa_tap;
  iov[iov_cnt].iov_len = sizeof(sa_tap);

Reply | Threaded
Open this post in threaded view
|

Re: iked - pfkey_write: writev failed: -> issue found

Martin Pieuchot
On 25/11/18(Sun) 10:52, David Hill wrote:

> On Sat, Oct 27, 2018 at 05:35:16PM +0200, Mark Patruck wrote:
> > I've found the reason for the error message
> >
> > iked[24455]: pfkey_write: writev failed: Invalid argument
> > iked[24455]: pfkey_write: writev failed: Invalid argument
> >
> > that comes up when the Child SA expires. (this affects 6.4 and -current)
> >
> > It appears when using a tap interface != default enc0 (for example enc5
> > in routing domain 5). So you can simply reproduce via
> >
> > $ doas ifconfig enc1 create
> >
> > use "tap enc1" in iked.conf     (hint: "tap enc0" works)
> >
> > For testing purposes it makes sense to lower "lifetime" to f.e. 2m.
> >
> >
> > On Tue, Sep 25, 2018 at 10:50:43AM -0300, Martin Pieuchot wrote:
> > > On 24/09/18(Mon) 20:21, Mark Patruck wrote:
> > > > Hi Martin,
> > > >
> > > > if you need additional info or have a diff to test, drop me a
> > > > note.
> > >
> > > I don't have time to look at this, better send a report to bugs@, you
> > > could also poke patrick@ to see if he has some ideas.
> >
> > --
> > Mark Patruck ( mark at wrapped.cx )
> > GPG key 0xF2865E51 / 187F F6D3 EE04 1DCE 1C74  F644 0D3C F66F F286 5E51
> >
> > http://www.wrapped.cx
> >
>
> I hit this too.
>
> in pfkey_sa, if the action is SADB_DELETE, the code skips (goto) ahead,
> so sa_tap is left uninitialized.  I tried the following diff first,
> thinking sa_tap wasn't being initialized in the SADB_DELETE case.  But
> it didn't help.
>
> Index: pfkey.c
> ===================================================================
> RCS file: /cvs/src/sbin/iked/pfkey.c,v
> retrieving revision 1.59
> diff -u -p -r1.59 pfkey.c
> --- pfkey.c 27 Nov 2017 18:39:35 -0000 1.59
> +++ pfkey.c 25 Nov 2018 15:46:32 -0000
> @@ -530,6 +530,13 @@ pfkey_sa(int sd, uint8_t satype, uint8_t
>   bzero(&sa_ltime_hard, sizeof(sa_ltime_hard));
>   bzero(&sa_ltime_soft, sizeof(sa_ltime_soft));
>  
> + if (pol->pol_tap != 0) {
> + bzero(&sa_tap, sizeof(sa_tap));
> + sa_tap.sadb_x_tap_exttype = SADB_X_EXT_TAP;
> + sa_tap.sadb_x_tap_len = sizeof(sa_tap) / 8;
> + sa_tap.sadb_x_tap_unit = pol->pol_tap;
> + }
> +
>   if (action == SADB_DELETE)
>   goto send;
>  
> @@ -641,13 +648,6 @@ pfkey_sa(int sd, uint8_t satype, uint8_t
>   sa_tag.sadb_x_tag_taglen = strlen(tag) + 1;
>   } else
>   tag = NULL;
> -
> - if (pol->pol_tap != 0) {
> - bzero(&sa_tap, sizeof(sa_tap));
> - sa_tap.sadb_x_tap_exttype = SADB_X_EXT_TAP;
> - sa_tap.sadb_x_tap_len = sizeof(sa_tap) / 8;
> - sa_tap.sadb_x_tap_unit = pol->pol_tap;
> - }
>  
>   send:
>   iov_cnt = 0;
>
>
> So, i reversed the logic and thought maybe SADB_DELETE doesn't want
> sa_tap to be part of the iov and came up with this diff.  I no longer
> get writev errors on rekey.  I am not sure if it is correct as-is
> though.
>
> Index: pfkey.c
> ===================================================================
> RCS file: /cvs/src/sbin/iked/pfkey.c,v
> retrieving revision 1.59
> diff -u -p -r1.59 pfkey.c
> --- pfkey.c 27 Nov 2017 18:39:35 -0000 1.59
> +++ pfkey.c 25 Nov 2018 15:37:11 -0000
> @@ -764,7 +764,7 @@ pfkey_sa(int sd, uint8_t satype, uint8_t
>   iov_cnt++;
>   }
/>  
> - if (pol->pol_tap != 0) {
> + if (pol->pol_tap != 0 && action != SADB_DELETE) {
>   /* enc(4) device tap unit */
>   iov[iov_cnt].iov_base = &sa_tap;
>   iov[iov_cnt].iov_len = sizeof(sa_tap);

Could you build a kernel with ENCDEBUG defined, set `encdebug' to a non
0 value and look for any "pfkeyv2_parsemessage" error?  This should
hopefully help us :)

Reply | Threaded
Open this post in threaded view
|

Re: iked - pfkey_write: writev failed: -> issue found

David Hill-3
On Wed, Nov 28, 2018 at 07:12:56PM -0200, Martin Pieuchot wrote:

> On 25/11/18(Sun) 10:52, David Hill wrote:
> > On Sat, Oct 27, 2018 at 05:35:16PM +0200, Mark Patruck wrote:
> > > I've found the reason for the error message
> > >
> > > iked[24455]: pfkey_write: writev failed: Invalid argument
> > > iked[24455]: pfkey_write: writev failed: Invalid argument
> > >
> > > that comes up when the Child SA expires. (this affects 6.4 and -current)
> > >
> > > It appears when using a tap interface != default enc0 (for example enc5
> > > in routing domain 5). So you can simply reproduce via
> > >
> > > $ doas ifconfig enc1 create
> > >
> > > use "tap enc1" in iked.conf     (hint: "tap enc0" works)
> > >
> > > For testing purposes it makes sense to lower "lifetime" to f.e. 2m.
> > >
> > >
> > > On Tue, Sep 25, 2018 at 10:50:43AM -0300, Martin Pieuchot wrote:
> > > > On 24/09/18(Mon) 20:21, Mark Patruck wrote:
> > > > > Hi Martin,
> > > > >
> > > > > if you need additional info or have a diff to test, drop me a
> > > > > note.
> > > >
> > > > I don't have time to look at this, better send a report to bugs@, you
> > > > could also poke patrick@ to see if he has some ideas.
> > >
> > > --
> > > Mark Patruck ( mark at wrapped.cx )
> > > GPG key 0xF2865E51 / 187F F6D3 EE04 1DCE 1C74  F644 0D3C F66F F286 5E51
> > >
> > > http://www.wrapped.cx
> > >
> >
> > I hit this too.
> >
> > in pfkey_sa, if the action is SADB_DELETE, the code skips (goto) ahead,
> > so sa_tap is left uninitialized.  I tried the following diff first,
> > thinking sa_tap wasn't being initialized in the SADB_DELETE case.  But
> > it didn't help.
> >
> > Index: pfkey.c
> > ===================================================================
> > RCS file: /cvs/src/sbin/iked/pfkey.c,v
> > retrieving revision 1.59
> > diff -u -p -r1.59 pfkey.c
> > --- pfkey.c 27 Nov 2017 18:39:35 -0000 1.59
> > +++ pfkey.c 25 Nov 2018 15:46:32 -0000
> > @@ -530,6 +530,13 @@ pfkey_sa(int sd, uint8_t satype, uint8_t
> >   bzero(&sa_ltime_hard, sizeof(sa_ltime_hard));
> >   bzero(&sa_ltime_soft, sizeof(sa_ltime_soft));
> >  
> > + if (pol->pol_tap != 0) {
> > + bzero(&sa_tap, sizeof(sa_tap));
> > + sa_tap.sadb_x_tap_exttype = SADB_X_EXT_TAP;
> > + sa_tap.sadb_x_tap_len = sizeof(sa_tap) / 8;
> > + sa_tap.sadb_x_tap_unit = pol->pol_tap;
> > + }
> > +
> >   if (action == SADB_DELETE)
> >   goto send;
> >  
> > @@ -641,13 +648,6 @@ pfkey_sa(int sd, uint8_t satype, uint8_t
> >   sa_tag.sadb_x_tag_taglen = strlen(tag) + 1;
> >   } else
> >   tag = NULL;
> > -
> > - if (pol->pol_tap != 0) {
> > - bzero(&sa_tap, sizeof(sa_tap));
> > - sa_tap.sadb_x_tap_exttype = SADB_X_EXT_TAP;
> > - sa_tap.sadb_x_tap_len = sizeof(sa_tap) / 8;
> > - sa_tap.sadb_x_tap_unit = pol->pol_tap;
> > - }
> >  
> >   send:
> >   iov_cnt = 0;
> >
> >
> > So, i reversed the logic and thought maybe SADB_DELETE doesn't want
> > sa_tap to be part of the iov and came up with this diff.  I no longer
> > get writev errors on rekey.  I am not sure if it is correct as-is
> > though.
> >
> > Index: pfkey.c
> > ===================================================================
> > RCS file: /cvs/src/sbin/iked/pfkey.c,v
> > retrieving revision 1.59
> > diff -u -p -r1.59 pfkey.c
> > --- pfkey.c 27 Nov 2017 18:39:35 -0000 1.59
> > +++ pfkey.c 25 Nov 2018 15:37:11 -0000
> > @@ -764,7 +764,7 @@ pfkey_sa(int sd, uint8_t satype, uint8_t
> >   iov_cnt++;
> >   }
> />  
> > - if (pol->pol_tap != 0) {
> > + if (pol->pol_tap != 0 && action != SADB_DELETE) {
> >   /* enc(4) device tap unit */
> >   iov[iov_cnt].iov_base = &sa_tap;
> >   iov[iov_cnt].iov_len = sizeof(sa_tap);
>
> Could you build a kernel with ENCDEBUG defined, set `encdebug' to a non
> 0 value and look for any "pfkeyv2_parsemessage" error?  This should
> hopefully help us :)
>

Nov 29 16:33:23 host1 /bsd: pfkeyv2_parsemessage: extension header 34 not permitted on message type 4
Nov 29 16:33:23 host1 /bsd: pfkeyv2_parsemessage: extension header 34 not permitted on message type 4
Nov 29 16:34:16 host1 /bsd: pfkeyv2_parsemessage: extension header 34 not permitted on message type 4
Nov 29 16:34:16 host1 /bsd: pfkeyv2_parsemessage: extension header 34 not permitted on message type 4
Nov 29 16:35:08 host1 /bsd: pfkeyv2_parsemessage: extension header 34 not permitted on message type 4
Nov 29 16:35:08 host1 /bsd: pfkeyv2_parsemessage: extension header 34 not permitted on message type 4
Nov 29 16:37:05 host1 /bsd: pfkeyv2_parsemessage: length not a multiple of 64
Nov 29 16:37:05 host1 /bsd: pfkeyv2_parsemessage: length not a multiple of 64

Reply | Threaded
Open this post in threaded view
|

Re: iked - pfkey_write: writev failed: -> issue found

Mark Patruck
Thanks David. Didn't have time to look into this.

On Thu, Nov 29, 2018 at 06:44:52PM -0500, David Hill wrote:

> On Wed, Nov 28, 2018 at 07:12:56PM -0200, Martin Pieuchot wrote:
> > On 25/11/18(Sun) 10:52, David Hill wrote:
> > > On Sat, Oct 27, 2018 at 05:35:16PM +0200, Mark Patruck wrote:
> > > > I've found the reason for the error message
> > > >
> > > > iked[24455]: pfkey_write: writev failed: Invalid argument
> > > > iked[24455]: pfkey_write: writev failed: Invalid argument
> > > >
> > > > that comes up when the Child SA expires. (this affects 6.4 and -current)
> > > >
> > > > It appears when using a tap interface != default enc0 (for example enc5
> > > > in routing domain 5). So you can simply reproduce via
> > > >
> > > > $ doas ifconfig enc1 create
> > > >
> > > > use "tap enc1" in iked.conf     (hint: "tap enc0" works)
> > > >
> > > > For testing purposes it makes sense to lower "lifetime" to f.e. 2m.
> > > >
> > > >
> > > > On Tue, Sep 25, 2018 at 10:50:43AM -0300, Martin Pieuchot wrote:
> > > > > On 24/09/18(Mon) 20:21, Mark Patruck wrote:
> > > > > > Hi Martin,
> > > > > >
> > > > > > if you need additional info or have a diff to test, drop me a
> > > > > > note.
> > > > >
> > > > > I don't have time to look at this, better send a report to bugs@, you
> > > > > could also poke patrick@ to see if he has some ideas.
> > > >
> > > > --
> > > > Mark Patruck ( mark at wrapped.cx )
> > > > GPG key 0xF2865E51 / 187F F6D3 EE04 1DCE 1C74  F644 0D3C F66F F286 5E51
> > > >
> > > > http://www.wrapped.cx
> > > >
> > >
> > > I hit this too.
> > >
> > > in pfkey_sa, if the action is SADB_DELETE, the code skips (goto) ahead,
> > > so sa_tap is left uninitialized.  I tried the following diff first,
> > > thinking sa_tap wasn't being initialized in the SADB_DELETE case.  But
> > > it didn't help.
> > >
> > > Index: pfkey.c
> > > ===================================================================
> > > RCS file: /cvs/src/sbin/iked/pfkey.c,v
> > > retrieving revision 1.59
> > > diff -u -p -r1.59 pfkey.c
> > > --- pfkey.c 27 Nov 2017 18:39:35 -0000 1.59
> > > +++ pfkey.c 25 Nov 2018 15:46:32 -0000
> > > @@ -530,6 +530,13 @@ pfkey_sa(int sd, uint8_t satype, uint8_t
> > >   bzero(&sa_ltime_hard, sizeof(sa_ltime_hard));
> > >   bzero(&sa_ltime_soft, sizeof(sa_ltime_soft));
> > >  
> > > + if (pol->pol_tap != 0) {
> > > + bzero(&sa_tap, sizeof(sa_tap));
> > > + sa_tap.sadb_x_tap_exttype = SADB_X_EXT_TAP;
> > > + sa_tap.sadb_x_tap_len = sizeof(sa_tap) / 8;
> > > + sa_tap.sadb_x_tap_unit = pol->pol_tap;
> > > + }
> > > +
> > >   if (action == SADB_DELETE)
> > >   goto send;
> > >  
> > > @@ -641,13 +648,6 @@ pfkey_sa(int sd, uint8_t satype, uint8_t
> > >   sa_tag.sadb_x_tag_taglen = strlen(tag) + 1;
> > >   } else
> > >   tag = NULL;
> > > -
> > > - if (pol->pol_tap != 0) {
> > > - bzero(&sa_tap, sizeof(sa_tap));
> > > - sa_tap.sadb_x_tap_exttype = SADB_X_EXT_TAP;
> > > - sa_tap.sadb_x_tap_len = sizeof(sa_tap) / 8;
> > > - sa_tap.sadb_x_tap_unit = pol->pol_tap;
> > > - }
> > >  
> > >   send:
> > >   iov_cnt = 0;
> > >
> > >
> > > So, i reversed the logic and thought maybe SADB_DELETE doesn't want
> > > sa_tap to be part of the iov and came up with this diff.  I no longer
> > > get writev errors on rekey.  I am not sure if it is correct as-is
> > > though.
> > >
> > > Index: pfkey.c
> > > ===================================================================
> > > RCS file: /cvs/src/sbin/iked/pfkey.c,v
> > > retrieving revision 1.59
> > > diff -u -p -r1.59 pfkey.c
> > > --- pfkey.c 27 Nov 2017 18:39:35 -0000 1.59
> > > +++ pfkey.c 25 Nov 2018 15:37:11 -0000
> > > @@ -764,7 +764,7 @@ pfkey_sa(int sd, uint8_t satype, uint8_t
> > >   iov_cnt++;
> > >   }
> > />  
> > > - if (pol->pol_tap != 0) {
> > > + if (pol->pol_tap != 0 && action != SADB_DELETE) {
> > >   /* enc(4) device tap unit */
> > >   iov[iov_cnt].iov_base = &sa_tap;
> > >   iov[iov_cnt].iov_len = sizeof(sa_tap);
> >
> > Could you build a kernel with ENCDEBUG defined, set `encdebug' to a non
> > 0 value and look for any "pfkeyv2_parsemessage" error?  This should
> > hopefully help us :)
> >
>
> Nov 29 16:33:23 host1 /bsd: pfkeyv2_parsemessage: extension header 34 not permitted on message type 4
> Nov 29 16:33:23 host1 /bsd: pfkeyv2_parsemessage: extension header 34 not permitted on message type 4
> Nov 29 16:34:16 host1 /bsd: pfkeyv2_parsemessage: extension header 34 not permitted on message type 4
> Nov 29 16:34:16 host1 /bsd: pfkeyv2_parsemessage: extension header 34 not permitted on message type 4
> Nov 29 16:35:08 host1 /bsd: pfkeyv2_parsemessage: extension header 34 not permitted on message type 4
> Nov 29 16:35:08 host1 /bsd: pfkeyv2_parsemessage: extension header 34 not permitted on message type 4
> Nov 29 16:37:05 host1 /bsd: pfkeyv2_parsemessage: length not a multiple of 64
> Nov 29 16:37:05 host1 /bsd: pfkeyv2_parsemessage: length not a multiple of 64
>

--
Mark Patruck ( mark at wrapped.cx )
GPG key 0xF2865E51 / 187F F6D3 EE04 1DCE 1C74  F644 0D3C F66F F286 5E51

https://www.wrapped.cx