DHCPv4 does not work - 2 binding objects but one

[Scott Yu]

Hi,

I'm using the 2.0.0 beta for DHCPv4 solution, but I met an error that's show 2 binding objects but one, and client cannot get IPv4 address normally, can you have a check?

Server: Windows7 SP1

Client: Win8 or Win7

2013-01-23 21:30:10,442 [pool-14-thread-223] INFO  request.DhcpV4DiscoverProcessor - Processing Discover from: chAddr=101f745c299f

2013-01-23 21:30:10,470 [pool-12-thread-147] INFO  binding.BaseBindingManager - Found current binding for IA: duid=101f745c299f iatype=0(V4) iaid=0

2013-01-23 21:30:10,472 [pool-12-thread-147] INFO  binding.BaseBindingManager - Found binding pool: 192.168.0.50-192.168.0.99

2013-01-23 21:30:10,473 [pool-12-thread-147] INFO  binding.BaseBindingManager - Found binding pool: 192.168.0.50-192.168.0.99

2013-01-23 21:30:10,476 [pool-12-thread-147] INFO  binding.BaseBindingManager - Successfully built Binding object: 

IA: duid=101f745c299f iatype=0(V4) iaid=0 state=1(Advertised)

IA_ADDR:  ip=192.168.0.50 state=1(Advertised) startTime=2013-01-23T21:30:01.762+0800 preferredEndTime=2013-01-23T22:00:01.762+0800 validEndTime=2013-01-23T22:00:01.762+0800

IA_ADDR:  ip=192.168.0.51 state=1(Advertised) startTime=2013-01-23T21:30:01.763+0800 preferredEndTime=2013-01-23T22:00:01.763+0800 validEndTime=2013-01-23T22:00:01.763+0800

2013-01-23 21:30:10,477 [pool-12-thread-147] INFO  binding.BaseBindingManager - Updating dynamic binding: 

IA: duid=101f745c299f iatype=0(V4) iaid=0 state=1(Advertised)

IA_ADDR:  ip=192.168.0.50 state=1(Advertised) startTime=2013-01-23T21:30:01.762+0800 preferredEndTime=2013-01-23T22:00:01.762+0800 validEndTime=2013-01-23T22:00:01.762+0800

IA_ADDR:  ip=192.168.0.51 state=1(Advertised) startTime=2013-01-23T21:30:01.763+0800 preferredEndTime=2013-01-23T22:00:01.763+0800 validEndTime=2013-01-23T22:00:01.763+0800

2013-01-23 21:30:10,478 [pool-12-thread-147] DEBUG binding.BaseBindingManager - Updating binding times for address: 192.168.0.50 preferred=1800000, valid=1800000

2013-01-23 21:30:10,478 [pool-12-thread-147] DEBUG binding.BaseBindingManager - Updating binding times for address: 192.168.0.51 preferred=1800000, valid=1800000

2013-01-23 21:30:10,482 [pool-14-thread-223] INFO  binding.BaseBindingManager - Found current binding for IA: duid=101f745c299f iatype=0(V4) iaid=0

2013-01-23 21:30:10,484 [pool-14-thread-223] INFO  binding.BaseBindingManager - Found binding pool: 192.168.0.50-192.168.0.99

2013-01-23 21:30:10,486 [pool-14-thread-223] INFO  binding.BaseBindingManager - Found binding pool: 192.168.0.50-192.168.0.99

2013-01-23 21:30:10,488 [pool-14-thread-223] INFO  binding.BaseBindingManager - Successfully built Binding object: 

IA: duid=101f745c299f iatype=0(V4) iaid=0 state=1(Advertised)

IA_ADDR:  ip=192.168.0.50 state=1(Advertised) startTime=2013-01-23T21:30:01.762+0800 preferredEndTime=2013-01-23T22:00:01.762+0800 validEndTime=2013-01-23T22:00:01.762+0800

IA_ADDR:  ip=192.168.0.51 state=1(Advertised) startTime=2013-01-23T21:30:01.763+0800 preferredEndTime=2013-01-23T22:00:01.763+0800 validEndTime=2013-01-23T22:00:01.763+0800

2013-01-23 21:30:10,490 [pool-14-thread-223] INFO  binding.BaseBindingManager - Updating dynamic binding: 

IA: duid=101f745c299f iatype=0(V4) iaid=0 state=1(Advertised)

IA_ADDR:  ip=192.168.0.50 state=1(Advertised) startTime=2013-01-23T21:30:01.762+0800 preferredEndTime=2013-01-23T22:00:01.762+0800 validEndTime=2013-01-23T22:00:01.762+0800

IA_ADDR:  ip=192.168.0.51 state=1(Advertised) startTime=2013-01-23T21:30:01.763+0800 preferredEndTime=2013-01-23T22:00:01.763+0800 validEndTime=2013-01-23T22:00:01.763+0800

2013-01-23 21:30:10,491 [pool-14-thread-223] DEBUG binding.BaseBindingManager - Updating binding times for address: 192.168.0.50 preferred=1800000, valid=1800000

2013-01-23 21:30:10,491 [pool-14-thread-223] DEBUG binding.BaseBindingManager - Updating binding times for address: 192.168.0.51 preferred=1800000, valid=1800000

2013-01-23 21:30:10,521 [pool-12-thread-147] ERROR request.BaseDhcpV4Processor - Expected only one bindingObject in v4 Binding, but found 2bindingObjects

2013-01-23 21:30:10,524 [pool-12-thread-147] DEBUG request.BaseDhcpV4Processor - Returning: Offer to 0.0.0.0:68 (htype=1, hlen=6, hops=0, xid=1336571549, secs=0, flags=0, ciaddr=0.0.0.0, yiaddr=0.0.0.0, siaddr=0.0.0.0, giaddr=0.0.0.0, chaddr=101f745c299f)

dhcpOptions

DhcpV4ServerIdOption

<!--DHCPv4 ServerID must be a local IP address-->

<ipAddress xmlns:dhc="http://ietf.org/dhc/dhcpv6">192.168.0.1</ipAddress>

DhcpV4MsgTypeOption

<unsignedByte>2</unsignedByte>

2013-01-23 21:30:10,525 [pool-12-thread-147] DEBUG request.BaseDhcpV4Processor - Removed recent message: Discover from 0.0.0.0:68 (htype=1, hlen=6, hops=0, xid=1336571549, secs=3328, flags=0, ciaddr=0.0.0.0, yiaddr=0.0.0.0, siaddr=0.0.0.0, giaddr=0.0.0.0, chaddr=101f745c299f)

2013-01-23 21:30:10,526 [pool-12-thread-147] DEBUG message.DhcpV4Message - Encoding DhcpMessage for: 0.0.0.0:68

2013-01-23 21:30:10,527 [pool-12-thread-147] DEBUG message.DhcpV4Message - DhcpMessage encoded.

2013-01-23 21:30:10,527 [pool-12-thread-147] DEBUG netty.DhcpV4ChannelEncoder - Encoded message buffer limit=250

2013-01-23 21:30:10,530 [pool-12-thread-147] WARN  channel.SimpleChannelHandler - EXCEPTION, please implement com.jagornet.dhcpv6.server.netty.DhcpV4ChannelHandler.exceptionCaught() for proper handling.

java.net.BindException: Cannot assign requested address: Datagram send failed

at java.net.PlainDatagramSocketImpl.send(Native Method)

at java.net.DatagramSocket.send(Unknown Source)

at org.jboss.netty.channel.socket.oio.OioDatagramWorker.write(OioDatagramWorker.java:113)

at org.jboss.netty.channel.socket.oio.OioDatagramPipelineSink.eventSunk(OioDatagramPipelineSink.java:76)

at org.jboss.netty.handler.logging.LoggingHandler.handleDownstream(LoggingHandler.java:232)

at org.jboss.netty.channel.Channels.write(Channels.java:626)

at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:65)

at org.jboss.netty.handler.execution.ExecutionHandler.handleDownstream(ExecutionHandler.java:165)

at org.jboss.netty.channel.Channels.write(Channels.java:605)

at org.jboss.netty.channel.AbstractChannel.write(AbstractChannel.java:249)

at org.jboss.netty.channel.socket.oio.OioDatagramChannel.write(OioDatagramChannel.java:128)

at com.jagornet.dhcpv6.server.netty.DhcpV4ChannelHandler.messageReceived(DhcpV4ChannelHandler.java:97)

at org.jboss.netty.handler.execution.ChannelUpstreamEventRunnable.run(ChannelUpstreamEventRunnable.java:44)

at org.jboss.netty.handler.execution.OrderedMemoryAwareThreadPoolExecutor$ChildExecutor.run(OrderedMemoryAwareThreadPoolExecutor.java:312)

at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

at java.lang.Thread.run(Unknown Source)

2013-01-23 21:30:10,556 [pool-14-thread-223] ERROR request.BaseDhcpV4Processor - Expected only one bindingObject in v4 Binding, but found 2bindingObjects

[Scott Yu]

Attached conf file. just modify something about v4 pool setting, but still got same failure.

Scott Yu於 2013年1月24日星期四UTC+8下午9時34分42秒寫道：

[Greg Rabil]

Hi Scott,

In order to help us diagnose this issue, please follow these steps:

1.  Stop the server.

2.  Delete the db/derby directory.

3.  Delete the log/* contents.

4.  Restart the server.

5.  Start the client.

6.  Zip the db/* and log/* directories and post them here.

Thanks,

Greg Rabil

[Scott Yu]

Hi, Greg,

Here come you need that is follow the steps you asked. Thank you.

Greg Rabil於 2013年1月24日星期四UTC+8下午10時26分57秒寫道：

[Greg Rabil]

Hi Scott,

This latest log indicates a different problem from what you had originally reported.  The server is unable to parse the client's FQDN option (81).  Unit tests for the server indicate that it is able of processing properly formatted FQDN option, but something is a problem with the packet from the client with MAC=888888888788 (see below).  Is that a test client of some sort?  The MAC address seems strange.  Is it possible that it is not formatting the FQDN option correctly?  Please run Wireshark to capture the packets from this client and provide the capture for analysis.

2013-01-25 14:53:22,634 [New I/O datagram worker #1'-'1] DEBUG message.DhcpV4Message - chaddr=888888888788

2013-01-25 14:53:22,634 [Old I/O datagram worker ([id: 0x0904eabb, /192.168.0.1:67])] DEBUG message.DhcpV4Message - Option code=61

2013-01-25 14:53:22,634 [New I/O datagram worker #1'-'1] DEBUG message.DhcpV4Message - sname=

2013-01-25 14:53:22,635 [New I/O datagram worker #1'-'1] DEBUG message.DhcpV4Message - file=

2013-01-25 14:53:22,635 [Old I/O datagram worker ([id: 0x0904eabb, /192.168.0.1:67])] DEBUG base.BaseDhcpOption - DhcpUnknownOption reports length=7:  bytes remaining in buffer=55

2013-01-25 14:53:22,635 [New I/O datagram worker #1'-'1] DEBUG message.DhcpV4Message - Option code=53

2013-01-25 14:53:22,636 [Old I/O datagram worker ([id: 0x0904eabb, /192.168.0.1:67])] DEBUG message.DhcpV4Message - Option code=50

2013-01-25 14:53:22,636 [New I/O datagram worker #1'-'1] DEBUG base.BaseDhcpOption - DhcpV4MsgTypeOption reports length=1:  bytes remaining in buffer=58

2013-01-25 14:53:22,636 [Old I/O datagram worker ([id: 0x0904eabb, /192.168.0.1:67])] DEBUG base.BaseDhcpOption - DhcpV4RequestedIpAddressOption reports length=4:  bytes remaining in buffer=46

2013-01-25 14:53:22,637 [New I/O datagram worker #1'-'1] DEBUG message.DhcpV4Message - Option code=61

2013-01-25 14:53:22,637 [Old I/O datagram worker ([id: 0x0904eabb, /192.168.0.1:67])] DEBUG message.DhcpV4Message - Option code=12

2013-01-25 14:53:22,638 [New I/O datagram worker #1'-'1] DEBUG base.BaseDhcpOption - DhcpUnknownOption reports length=7:  bytes remaining in buffer=55

2013-01-25 14:53:22,638 [Old I/O datagram worker ([id: 0x0904eabb, /192.168.0.1:67])] DEBUG base.BaseDhcpOption - DhcpV4HostnameOption reports length=3:  bytes remaining in buffer=40

2013-01-25 14:53:22,638 [New I/O datagram worker #1'-'1] DEBUG message.DhcpV4Message - Option code=50

2013-01-25 14:53:22,639 [Old I/O datagram worker ([id: 0x0904eabb, /192.168.0.1:67])] DEBUG message.DhcpV4Message - Option code=81

2013-01-25 14:53:22,639 [New I/O datagram worker #1'-'1] DEBUG base.BaseDhcpOption - DhcpV4RequestedIpAddressOption reports length=4:  bytes remaining in buffer=46

2013-01-25 14:53:22,640 [Old I/O datagram worker ([id: 0x0904eabb, /192.168.0.1:67])] DEBUG base.BaseDhcpOption - DhcpV4ClientFqdnOption reports length=6:  bytes remaining in buffer=35

2013-01-25 14:53:22,640 [New I/O datagram worker #1'-'1] DEBUG message.DhcpV4Message - Option code=12

2013-01-25 14:53:22,641 [New I/O datagram worker #1'-'1] DEBUG base.BaseDhcpOption - DhcpV4HostnameOption reports length=3:  bytes remaining in buffer=40

2013-01-25 14:53:22,642 [New I/O datagram worker #1'-'1] DEBUG message.DhcpV4Message - Option code=81

2013-01-25 14:53:22,643 [New I/O datagram worker #1'-'1] DEBUG base.BaseDhcpOption - DhcpV4ClientFqdnOption reports length=6:  bytes remaining in buffer=35

2013-01-25 14:53:22,645 [pool-11-thread-5] WARN  channel.SimpleChannelHandler - EXCEPTION, please implement com.jagornet.dhcpv6.server.netty.DhcpV4ChannelHandler.exceptionCaught() for proper handling.

java.nio.BufferUnderflowException

at java.nio.HeapByteBuffer.get(Unknown Source)

at java.nio.ByteBuffer.get(Unknown Source)

at com.jagornet.dhcpv6.option.base.BaseDomainNameOption.decodeDomainName(BaseDomainNameOption.java:144)

at com.jagornet.dhcpv6.option.v4.DhcpV4ClientFqdnOption.decode(DhcpV4ClientFqdnOption.java:119)

at com.jagornet.dhcpv6.message.DhcpV4Message.decodeOptions(DhcpV4Message.java:394)

at com.jagornet.dhcpv6.message.DhcpV4Message.decode(DhcpV4Message.java:361)

at com.jagornet.dhcpv6.message.DhcpV4Message.decode(DhcpV4Message.java:283)

at com.jagornet.dhcpv6.server.netty.DhcpV4ChannelDecoder.decode(DhcpV4ChannelDecoder.java:78)

[Greg Rabil]

Hi again Scott,

Please ignore the previous post.  We have reproduced the issue using a Windows 7 client configured to send option 81 with the deprecated ASCII encoding for the FQDN option.  Issue 21 has been opened for this problem with the Jagornet DHCPv6 Server.  A fix has been made and is being tested.  This fix is expected to be included in the upcoming release candidate.

Thank you for reporting this problem and for your interest in Jagornet DHCPv6.

Regards,

Greg

[Scott Yu]

Hi, Greg,

Okay, good to see you can repro this issue on your side and gonna be fix, I try to repro the original issue that's I posted, once it getting reprouceable will post here.

Btw, may I  know the next release schedule? 

Greg Rabil於 2013年1月28日星期一UTC+8下午12時02分26秒寫道：