[Dibbler-devel] git version 26.07 10:00 works (mostly)

Mircea Ciocan mirceac at gmail.com
Thu Jul 28 16:44:04 CEST 2016


Dear Tomasz, under this message I've put a piece of log with the devugging
activated for the whole process of rejecting an address up to the segfault.

I have expanded a bit the debut message for the ipaddr_add_or_del()
function to print all its parameters and also added your patch for the
:GetSize function, but there I have to let you look into it, AFAIK is
everything that calls something like: (*opt)->whatever when the object is
screwed it crashes :(.

Coming back to the address adding function, I was intercepting and printing
the return  codes as well to see what's happening, the bottom line is
addinf the address returns OK but deliting it returns failure, here is a
piece of log with the noise removed:

2016.07.28 16:25:17 Client Info      Received REPLY on
eth3/33,trans-id=0xf52e37, 3 opts: 3 1 2
2016.07.28 16:25:17 Client Notice    Address 2001:1:8::10/128 added to
eth3/33 interface.
[DEBUG] iface=eth3, addr=2001:1:8::10, prefix=128, preffered=54000,
valid=86400, add=1 ###
[DEBUG] rtnl_open returned 0
[DEBUG] rtnl_talk returned 0
This part seem to be working but it doesn't :(, I'm now done with the unit
test to see if when run indepndently this actually does something, could
you please explain for me the values of those parameters: preffered=54000,
valid=86400, what is their meaning ?

Afterwards this part fails with a -1 code and with a rather incorrect
message, nobody wanted to add but to delete the IP:
2016.07.28 16:25:21 Client Info      Sending DECLINE for IA(IAID=1)
2001:1:8::10 2016.07.28 16:25:21 Client Notice    Address 2001:1:8::10/128
deleted from eth3/33 interface.
[DEBUG] iface=eth3, addr=2001:1:8::10, prefix=128, preffered=0, valid=0,
add=0 ###
[DEBUG] rtnl_open returned 0
RTNETLINK answers: Cannot assign requested address
[DEBUG] rtnl_talk returned -1

I will do now the individual run and also modify the ip command in the
source to print the parameters when the address is added manually and let
you know.

 Cheers, MC
=============== LOG STARTS HERE ===============
# /usr/local/sbin/dibbler-client run  -w /etc/dibbler/eth3
| Dibbler - a portable DHCPv6, version 1.0.1 (CLIENT, Linux port)
| Authors : Tomasz Mrugalski<thomson(at)klub.com.pl>,Marek
Senderski<msend(at)o2.pl>
| Licence : GNU GPL v2 only. Developed at Gdansk University of Technology.
| Homepage: http://klub.com.pl/dhcpv6/
2016.07.28 16:25:16 Client Notice    My pid (22936) is stored in
/etc/dibbler/eth3/client.pid
### iface 1 lo (flags:65609) (mo bits:-2147483648)###
M flag!### iface 2 eth0 (flags:4099) (mo bits:64)###
### iface 3 wlan0 (flags:69699) (mo bits:-2147483632)###
M flag!### iface 33 eth3 (flags:69699) (mo bits:-2147483536)###
2016.07.28 16:25:16 Client Notice    Detected iface eth3/33,
MAC=a4:f7:d0:00:0d:5d.
2016.07.28 16:25:16 Client Notice    Detected iface wlan0/3,
MAC=18:5e:0f:11:7f:f6.
2016.07.28 16:25:16 Client Notice    Detected iface eth0/2,
MAC=54:ee:75:79:13:03.
2016.07.28 16:25:16 Client Notice    Detected iface lo/1,
MAC=00:00:00:00:00:00.
2016.07.28 16:25:16 Client Notice    Parsing /etc/dibbler/eth3/client.conf
config file...
2016.07.28 16:25:16 Client Debug     Parsing /etc/dibbler/eth3/client.conf
done, result=0(success)
2016.07.28 16:25:16 Client Debug     1 interface(s) specified in
/etc/dibbler/eth3/client.conf
2016.07.28 16:25:16 Client Error     Invalid length -1 set attempt was
ignored on the eth3/33 interface.
2016.07.28 16:25:16 Client Info      Interface eth3/33 configuration has
been loaded.
2016.07.28 16:25:16 Client Debug     DUID's value =
00:02:65:70:70:63:02:a0:33:df was loaded from client-duid file.
2016.07.28 16:25:16 Client Info      My DUID is
00:02:65:70:70:63:02:a0:33:df.
2016.07.28 16:25:16 Client Info      Loading old address database
(client-AddrMgr.xml), using built-in routines.
2016.07.28 16:25:16 Client Warning   Unable to open client-AddrMgr.xml.
2016.07.28 16:25:16 Client Debug     Bind reuse enabled (multiple instances
allowed).
2016.07.28 16:25:16 Client Notice    Creating control (::) socket on the
lo/1 interface.
### iface: lo(id=1), addr=::, port=546, ifaceonly=0 reuse=1###
2016.07.28 16:25:16 Client Notice    Creating socket
(addr=fe80::a6f7:d0ff:fe00:d5d) on eth3/33 interface.
### iface: eth3(id=33), addr=fe80::a6f7:d0ff:fe00:d5d, port=546,
ifaceonly=1 reuse=1###
2016.07.28 16:25:16 Client Debug     Initialising link-state detection for
interfaces: eth3/33
### iface 1 lo (flags:65609) (mo bits:-2147483648)###
M flag!### iface 2 eth0 (flags:4099) (mo bits:64)###
### iface 3 wlan0 (flags:69699) (mo bits:-2147483632)###
M flag!### iface 33 eth3 (flags:69699) (mo bits:-2147483536)###
2016.07.28 16:25:16 Client Notice    CONFIRM support compiled in.
2016.07.28 16:25:16 Client Info      Creating SOLICIT message with 1 IA(s),
no TA and 0 PD(s) on eth3/33 interface.
[DEBUG] <getSize() on option index 0
[DEBUG] opt=0x1ba3550
[DEBUG] opt-type=1
[DEBUG] <getSize() on option index 1
[DEBUG] opt=0x1ba3d30
[DEBUG] opt-type=3
[DEBUG] <getSize() on option index 2
[DEBUG] opt=0x1ba3e80
[DEBUG] opt-type=39
[DEBUG] <getSize() on option index 3
[DEBUG] opt=0x1ba3f40
[DEBUG] opt-type=8
[DEBUG] <getSize() on option index 4
[DEBUG] opt=0x1ba3d90
[DEBUG] opt-type=1
2016.07.28 16:25:16 Client Debug     Sending SOLICIT(opts:1 3 39 8 1 ) on
eth3/33 to multicast.
[DEBUG] <getSize() on option index 0
[DEBUG] opt=0x1ba3550
[DEBUG] opt-type=1
[DEBUG] <getSize() on option index 1
[DEBUG] opt=0x1ba3d30
[DEBUG] opt-type=3
[DEBUG] <getSize() on option index 2
[DEBUG] opt=0x1ba3e80
[DEBUG] opt-type=39
[DEBUG] <getSize() on option index 3
[DEBUG] opt=0x1ba3f40
[DEBUG] opt-type=8
[DEBUG] <getSize() on option index 4
[DEBUG] opt=0x1ba3d90
[DEBUG] opt-type=1
2016.07.28 16:25:16 Client Debug     Sleeping for 1 second(s).
2016.07.28 16:25:16 Client Debug     Received 80 bytes on interface eth3/33
(socket=6, addr=fe80::3e97:eff:fe86:9a7d).
2016.07.28 16:25:16 Client Info      Received ADVERTISE on
eth3/33,trans-id=0xb60416, 3 opts: 3 1 2
2016.07.28 16:25:16 Client Debug     Not executing external script (Notify
script disabled).
2016.07.28 16:25:16 Client Debug     Sleeping for 1 second(s).
2016.07.28 16:25:17 Client Info      Processing msg
(SOLICIT,transID=0xb60416,opts: 1 3 39 8 1)
2016.07.28 16:25:17 Client Info      Creating REQUEST. Backup server list
contains 1 server(s).
2016.07.28 16:25:17 Client Debug     Advertise from Server
ID=00:01:00:01:1f:2c:d2:34:3c:97:0e:86:9a:7d, preference=0.[using this]
[DEBUG] <getSize() on option index 0
[DEBUG] opt=0x1ba3550
[DEBUG] opt-type=1
[DEBUG] <getSize() on option index 1
[DEBUG] opt=0x1ba3d30
[DEBUG] opt-type=3
[DEBUG] <getSize() on option index 2
[DEBUG] opt=0x1ba3e80
[DEBUG] opt-type=39
[DEBUG] <getSize() on option index 3
[DEBUG] opt=0x1ba3d90
[DEBUG] opt-type=1
[DEBUG] <getSize() on option index 4
[DEBUG] opt=0x1ba4480
[DEBUG] opt-type=2
[DEBUG] <getSize() on option index 5
[DEBUG] opt=0x1ba4900
[DEBUG] opt-type=8
2016.07.28 16:25:17 Client Debug     Sending REQUEST(opts:1 3 39 1 2 8 ) on
eth3/33 to multicast.
[DEBUG] <getSize() on option index 0
[DEBUG] opt=0x1ba3550
[DEBUG] opt-type=1
[DEBUG] <getSize() on option index 1
[DEBUG] opt=0x1ba3d30
[DEBUG] opt-type=3
[DEBUG] <getSize() on option index 2
[DEBUG] opt=0x1ba3e80
[DEBUG] opt-type=39
[DEBUG] <getSize() on option index 3
[DEBUG] opt=0x1ba3d90
[DEBUG] opt-type=1
[DEBUG] <getSize() on option index 4
[DEBUG] opt=0x1ba4480
[DEBUG] opt-type=2
[DEBUG] <getSize() on option index 5
[DEBUG] opt=0x1ba4900
[DEBUG] opt-type=8
2016.07.28 16:25:17 Client Debug     Sleeping for 1 second(s).
2016.07.28 16:25:17 Client Debug     Received 80 bytes on interface eth3/33
(socket=6, addr=fe80::3e97:eff:fe86:9a7d).
2016.07.28 16:25:17 Client Info      Received REPLY on
eth3/33,trans-id=0xf52e37, 3 opts: 3 1 2
2016.07.28 16:25:17 Client Notice    Address 2001:1:8::10/128 added to
eth3/33 interface.
[DEBUG] iface=eth3, addr=2001:1:8::10, prefix=128, preffered=54000,
valid=86400, add=1 ###
[DEBUG] rtnl_open returned 0
[DEBUG] rtnl_talk returned 0
2016.07.28 16:25:17 Client Notice    Server set T1 and T2 to 0. Choosing
default (50%, 70% * prefered-lifetime): T1=27000, T2=37800
2016.07.28 16:25:17 Client Debug     Not executing external script (Notify
script disabled).
2016.07.28 16:25:17 Client Debug     Sleeping for 3 second(s).
2016.07.28 16:25:20 Client Debug     Sleeping for 1 second(s).
2016.07.28 16:25:21 Client Error     DAD inconclusive. Unable to determine
2001:1:8::10 address state. Assuming  TENTATIVE.
[DEBUG] <getSize() on option index 0
[DEBUG] opt=0x1ba41c0
[DEBUG] opt-type=1
[DEBUG] <getSize() on option index 1
[DEBUG] opt=0x1ba41e0
[DEBUG] opt-type=2
[DEBUG] <getSize() on option index 2
[DEBUG] opt=0x1ba4360
[DEBUG] opt-type=3
[DEBUG] <getSize() on option index 3
[DEBUG] opt=0x1ba43c0
[DEBUG] opt-type=8
2016.07.28 16:25:21 Client Debug     Sending DECLINE(opts:1 2 3 8 ) on
eth3/33 to multicast.
[DEBUG] <getSize() on option index 0
[DEBUG] opt=0x1ba41c0
[DEBUG] opt-type=1
[DEBUG] <getSize() on option index 1
[DEBUG] opt=0x1ba41e0
[DEBUG] opt-type=2
[DEBUG] <getSize() on option index 2
[DEBUG] opt=0x1ba4360
[DEBUG] opt-type=3
[DEBUG] <getSize() on option index 3
[DEBUG] opt=0x1ba43c0
[DEBUG] opt-type=8
2016.07.28 16:25:21 Client Info      Sending DECLINE for IA(IAID=1)
2001:1:8::10 2016.07.28 16:25:21 Client Notice    Address 2001:1:8::10/128
deleted from eth3/33 interface.
[DEBUG] iface=eth3, addr=2001:1:8::10, prefix=128, preffered=0, valid=0,
add=0 ###
[DEBUG] rtnl_open returned 0
RTNETLINK answers: Cannot assign requested address
[DEBUG] rtnl_talk returned -1

[DEBUG] <getSize() on option index 0
[DEBUG] opt=0x1ba4580
[DEBUG] opt-type=1
[DEBUG] <getSize() on option index 1
[DEBUG] opt=0x1ba4020
[DEBUG] opt-type=28983136
Segmentation fault (core dumped)


On Thu, Jul 28, 2016 at 3:12 PM, Mircea Ciocan <mirceac at gmail.com> wrote:

> Dear Tomasz, I will do some unit tests with the lowlevel-linux.c module,
> practically a mini ip command, because the most baffling stuff is not that
> it fails, but that it most of the time succeeds ( in normal situations )
> and sometimes fails.
> I will try to make it succeed all the time, even if the address fails the
> DAD it should still be there on the interface with that dadfail flag set
> but not missing.
> I will use first the old code that compiles on my machine and then the new
> code.
> Strange (for me) situation I've encountered during the experiments:
>
> I have set a host with a static IPv6 that was getting the final flag and
> all OK, then on the other host I've set the same IP and expecting to fail,
> strangely enough, it got the final flag and previous host got the dadfail
> flag, is this normal or is there any order or whoever finishes the DAD test
> first get the fail flag ?
>
> Maybe you can tell me if you know more details.
>
> Now back to the little unit test for the low level linux stuff.
>
>  Best regards, MC
>
>
>
>
> On Wed, Jul 27, 2016 at 10:25 PM, Tomasz Mrugalski <thomson at klub.com.pl>
> wrote:
>
>> On 27.07.2016 20:43, Mircea Ciocan wrote:
>> > Hello Tomasz, as expected the fact that the address duplicate address
>> > can't be assigned to the interface is indeed a kernel issue, when the
>> > assignment fails I have the following messages in the system log:
>> >
>> > Jul 27 14:20:53 kernel: [782286.129796] IPv6: eth3: IPv6 duplicate
>> > address 2001:1:8::10 detected!
>> > Jul 27 14:20:54 kernel: [782286.698279] IPv6: eth3: IPv6 duplicate
>> > address 2001:1:8::10 detected!
>> > Jul 27 14:20:57 kernel: [782289.705480] IPv6: eth3: IPv6 duplicate
>> > address 2001:1:8::10 detected!
>> > ....
>> >
>> > So I think that my hypothesis, that the kernel does not allow the DAD
>> > invalid address to be set is confirmed.
>> Am afraid that theory is incorrect. Try to add it manually with:
>> ip addr addr 2001:1:8::10 dev eth3
>>
>> and the addition *will* succeed. If you run "ip addr list" in a quick
>> loop, you will notice that the address is being added with tentative
>> flag set and then after a second or so dadfailed flag is added.
>>
>> > Now why the set function doesn't return an error cod is not clear to me
>> > but that#s another story.
>>
>> Dibbler assumes in several places that the address it added is present
>> on the interface and I don't want to change that logic. We need to find
>> out why the address assignment works when called from ip from command
>> line, but fails when called from dibbler code.
>>
>> > But the most important issue right now is the segfault when accessing
>> > the Options member via that list iterator. It seems that once this
>> > object is invalid segfaults happens.
>> > I have no clue why it becomes invalid, if is a list issue (most likely)
>> > but once it gets in this state is game over.
>> I suspect that the checkDecline logic is broken and somehow it puts a
>> NULL pointer on the declined IAs list. Have you had a chance to apply my
>> verbose patch:
>> https://gist.github.com/tomaszmrugalski/5d7afaa5efc042af2861b61b2bc5e574
>>
>> I suspect it will show that
>>
>> > One other thing is that considering addresses with unknown status as
>> > tentative was in my case a good idea, I don't think is altogether a
>> > better option but it will be cool that in a future release to have it as
>> > a configurable parameter.
>> Not really. The fact that dibbler thinks it added an address, but the
>> address was not really added is a bug. Adding configuration knobs on top
>> of that bug would make it an ugly kludge. This is not something I would
>> like to have. Especially that we don't know why the assignment failed,
>> so it could possibly fail in other cases and have false positives as a
>> result.
>>
>> > So if you have any idea how can we do something about this Options
>> > member and his unhappy list I will be so happy ;).
>> We'll get to that once the failed address assignment problem is
>> resolved. I don't want to skip any steps, sorry. If I jump in and solve
>> the checkDecline bug, I'm afraid the underlying problem would remain
>> unsolved.
>>
>> Tomek
>>
>> _______________________________________________
>> Dibbler-devel mailing list
>> Dibbler-devel at klub.com.pl
>> http://klub.com.pl/cgi-bin/mailman/listinfo/dibbler-devel
>>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://klub.com.pl/pipermail/dibbler-devel/attachments/20160728/2e714f1f/attachment-0001.html>


More information about the Dibbler-devel mailing list