Error in handling relay forward message

[Amit Kumar]

Hi ,

I have installed jagornet version 2.0. It is working fine for the clients on the same link. But showing error in handling relay forward messages and hence not replying with advertise message.

Please find below logs:

2012-06-22 12:23:58,300 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Decoding packet: size=159 localAddr=2001:4408:5220:128:0:0:0:2%2:547 remoteAddr=2001:4408:2:f900:0:0:ffff:1:547

2012-06-22 12:23:58,301 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Message type byte=12

2012-06-22 12:23:58,301 [New I/O datagram worker #2'-'1] DEBUG message.DhcpRelayMessage - Decoding DhcpRelayMessage from: /2001:4408:2:f900:0:0:ffff:1:547

2012-06-22 12:23:58,301 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - MessageType=Relay-Forward

2012-06-22 12:23:58,301 [New I/O datagram worker #2'-'1] DEBUG message.DhcpRelayMessage - HopCount=0

2012-06-22 12:23:58,301 [New I/O datagram worker #2'-'1] DEBUG message.DhcpRelayMessage - LinkAddress: /2001:4408:5220:27:0:0:0:1

2012-06-22 12:23:58,301 [New I/O datagram worker #2'-'1] DEBUG message.DhcpRelayMessage - PeerAddress: /fe80:0:0:0:16b:f4b:802b:8a8a

2012-06-22 12:23:58,301 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Option code=9

2012-06-22 12:23:58,301 [New I/O datagram worker #2'-'1] DEBUG base.BaseDhcpOption - Relay Message reports length=87:  bytes remaining in buffer=121

2012-06-22 12:23:58,301 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Decoding packet: size=87 localAddr=2001:4408:5220:27:0:0:0:1:547 remoteAddr=fe80:0:0:0:16b:f4b:802b:8a8a:0

2012-06-22 12:23:58,301 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Message type byte=1

2012-06-22 12:23:58,301 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Decoding DhcpMessage from: fe80:0:0:0:16b:f4b:802b:8a8a:0

2012-06-22 12:23:58,301 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - MessageType=Solicit

2012-06-22 12:23:58,301 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - TransactionId=4389032

2012-06-22 12:23:58,302 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Option code=8

2012-06-22 12:23:58,302 [New I/O datagram worker #2'-'1] DEBUG base.BaseDhcpOption - DhcpElapsedTimeOption reports length=2:  bytes remaining in buffer=79

2012-06-22 12:23:58,302 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Option code=1

2012-06-22 12:23:58,302 [New I/O datagram worker #2'-'1] DEBUG base.BaseDhcpOption - DhcpClientIdOption reports length=14:  bytes remaining in buffer=73

2012-06-22 12:23:58,302 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Option code=3

2012-06-22 12:23:58,302 [New I/O datagram worker #2'-'1] DEBUG option.DhcpIaNaOption - IA_NA option reports length=12:  bytes remaining in buffer=55

2012-06-22 12:23:58,303 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Option code=39

2012-06-22 12:23:58,303 [New I/O datagram worker #2'-'1] DEBUG base.BaseDhcpOption - DhcpClientFqdnOption reports length=9:  bytes remaining in buffer=39

2012-06-22 12:23:58,303 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Option code=16

2012-06-22 12:23:58,303 [New I/O datagram worker #2'-'1] DEBUG base.BaseDhcpOption - DhcpVendorClassOption reports length=14:  bytes remaining in buffer=26

2012-06-22 12:23:58,303 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Option code=6

2012-06-22 12:23:58,304 [New I/O datagram worker #2'-'1] DEBUG base.BaseDhcpOption - DhcpOptionRequestOption reports length=8:  bytes remaining in buffer=8

2012-06-22 12:23:58,304 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - DhcpMessage decoded.

2012-06-22 12:23:58,304 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Option code=18

2012-06-22 12:23:58,304 [New I/O datagram worker #2'-'1] DEBUG base.BaseDhcpOption - DhcpInterfaceIdOption reports length=4:  bytes remaining in buffer=30

2012-06-22 12:23:58,304 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Option code=37

2012-06-22 12:23:58,304 [New I/O datagram worker #2'-'1] DEBUG base.BaseDhcpOption - DhcpRemoteIdOption reports length=22:  bytes remaining in buffer=22

2012-06-22 12:23:58,306 [pool-3-thread-4] WARN  channel.SimpleChannelHandler - EXCEPTION, please implement com.jagornet.dhcpv6.server.netty.DhcpChannelHandler.exceptionCaught() for proper handling.

java.nio.BufferUnderflowException

        at java.nio.HeapByteBuffer.get(HeapByteBuffer.java:145)

        at java.nio.ByteBuffer.get(ByteBuffer.java:692)

        at com.jagornet.dhcpv6.option.OpaqueDataUtil.decodeDataOnly(OpaqueDataUtil.java:191)

        at com.jagornet.dhcpv6.option.DhcpRemoteIdOption.decode(DhcpRemoteIdOption.java:105)

        at com.jagornet.dhcpv6.message.DhcpMessage.decodeOptions(DhcpMessage.java:364)

        at com.jagornet.dhcpv6.message.DhcpRelayMessage.decode(DhcpRelayMessage.java:204)

        at com.jagornet.dhcpv6.message.DhcpMessage.decode(DhcpMessage.java:271)

        at com.jagornet.dhcpv6.server.netty.DhcpChannelDecoder.decode(DhcpChannelDecoder.java:76)

        at com.jagornet.dhcpv6.server.netty.DhcpUnicastChannelDecoder.decode(DhcpUnicastChannelDecoder.java:57)

        at org.jboss.netty.handler.codec.oneone.OneToOneDecoder.handleUpstream(OneToOneDecoder.java:67)

        at com.jagornet.dhcpv6.server.netty.DhcpChannelDecoder.handleUpstream(DhcpChannelDecoder.java:95)

        at org.jboss.netty.handler.logging.LoggingHandler.handleUpstream(LoggingHandler.java:226)

        at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268)

        at org.jboss.netty.channel.socket.nio.NioDatagramWorker.read(NioDatagramWorker.java:413)

        at org.jboss.netty.channel.socket.nio.NioDatagramWorker.processSelectedKeys(NioDatagramWorker.java:342)

        at org.jboss.netty.channel.socket.nio.NioDatagramWorker.run(NioDatagramWorker.java:255)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)

        at java.lang.Thread.run(Thread.java:679)

[Greg Rabil]

Hello,

The problem is not really with the relay forward message, but it is a bug in the decoding of the RemoteId option.  Thank you for reporting this issue.

Regards,

Greg Rabil

Jagornet Technologies

[Greg Rabil]

Issue 14 has been resolved.  The fix will be included in next release of Jagornet DHCPv6 Server 2.0.

Thanks again for finding and reporting the issue.

Regards,

Greg Rabil

Jagornet Technologies

[Amit Kumar]

Hi Greg,

Thanks for the bug fix.

Now I am running dhcpv6 from the source, but the problem is server is able to decode solicit message and also encoding advertise message as shown in log message. But client is not getting any advertise message (verified from wireshark traces)

Please find attached log file.

-- 
Thanks & Regards,

Amit Kumar,
Scientific Officer/ Scientist-SB
Ministry of Communications & Information Technology
Department of Information Technology
National Informatics Center
http://home.nic.in/

Mob: 9910611621 

--
You received this message because you are subscribed to the Google Groups "jagornet-dhcpv6-users" group.

To view this discussion on the web visit https://groups.google.com/d/msg/jagornet-dhcpv6-users/-/bwRwBvd_ls0J.

To post to this group, send email to jagornet-d...@googlegroups.com.
To unsubscribe from this group, send email to jagornet-dhcpv6-...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/jagornet-dhcpv6-users?hl=en.

--
Thanks & Regards,

Amit Kumar,
Scientific Officer/ Scientist-SB
Ministry of Communications & Information Technology
Department of Information Technology
National Informatics Center
http://home.nic.in/

Mob: 9910611621

[Greg Rabil]

Hi Amit,

The server appears to be operating correctly.  The Advertise is being sent to fe80:0:0:0:29e2:783d:7c33:553a. Are you able to verify that is the link-local address of your client? If so, then the problem you are having is most likely with your network or IPv6 stack. As you had indicated you were running CentOS 6, you should confirm that your firewall is turned off for both the client and server. This is a common issue because of the default settings for CentOS/RHEL firewall. See the following link to turn off firewalls - http://www.cyberciti.biz/faq/disable-linux-firewall-under-centos-rhel-fedora/ 

Regards,

Greg

To post to this group, send email to jagornet-dhcpv6-users@googlegroups.com.
To unsubscribe from this group, send email to jagornet-dhcpv6-users+unsub...@googlegroups.com.

For more options, visit this group at http://groups.google.com/group/jagornet-dhcpv6-users?hl=en.

[Amit Kumar]

Thanks Greg,

But actually firewall is turned off and also client ipv6 stack is working fine, because If I am running other DHCPv6 server, then clients are able to get the ipv6 address successfully. Also verified the link local address.

Please find attached log file and wireshark tarce...

-- 
Thanks & Regards,

Amit Kumar,
Scientific Officer/ Scientist-SB
Ministry of Communications & Information Technology
Department of Information Technology
National Informatics Center
http://home.nic.in/

Mob: 9910611621 

To view this discussion on the web visit https://groups.google.com/d/msg/jagornet-dhcpv6-users/-/DH40LHkSiB8J.

To post to this group, send email to jagornet-d...@googlegroups.com.
To unsubscribe from this group, send email to jagornet-dhcpv6-...@googlegroups.com.

[Amit Kumar]

Hi Greg,

Now I am able to serve solicit messages succesfully to the one for which I have done address binding based on the client DUID but for the other clients it says "failed to bind" and also the problem with the relay forward packets still persist.

Please find attached logs.

Note: I am running jagornet from the source (R 171)

-- 
Thanks & Regards,

Amit Kumar,
Scientific Officer/ Scientist-SB
Ministry of Communications & Information Technology
Department of Information Technology
National Informatics Center
http://home.nic.in/

Mob: 9910611621

[Greg Rabil]

Hi Amit,

The log indicates a problem caused by a NullPointerException being thrown by the server when logging a message for an old/expired binding.  This is a bug, which has been created and fixed (Issue 15). You may workaround the issue by stopping the server, deleting the jagornet/db/derby directory, and then restarting the server.  It may also be possible to workaround it by modifying the log4j settings for the 'log4j.category.com.jagornet' property from DEBUG to INFO.  Since you indicated you are running from source, you may also fix this NullPointerException issue by obtaining the fix which has been committed.

Thanks again for your help in reporting issues with this beta release.

Greg

To unsubscribe from this group, send email to jagornet-dhcpv6-users+unsubscri...@googlegroups.com.

For more options, visit this group at http://groups.google.com/group/jagornet-dhcpv6-users?hl=en.

--
Thanks & Regards,

Amit Kumar,
Scientific Officer/ Scientist-SB
Ministry of Communications & Information Technology
Department of Information Technology
National Informatics Center
http://home.nic.in/

Mob: 9910611621

--
You received this message because you are subscribed to the Google Groups "jagornet-dhcpv6-users" group.

[Amit Kumar]

Hi Greg,

I also did the same and resolved the issue. Now clients in the same LAN are able to get the ipv6 address successfully. 

But Jagornet still not able to process relay forward message and showing below error:

2012-06-27 08:47:57,542 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Decoding packet: size=159 localAddr=2001:4408:5220:128:0:0:0:2%2:547 remoteAddr=2001:4408:2:f900:0:0:ffff:1:547

2012-06-27 08:47:57,542 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Message type byte=12

2012-06-27 08:47:57,543 [New I/O datagram worker #2'-'1] DEBUG message.DhcpRelayMessage - Decoding DhcpRelayMessage from: /2001:4408:2:f900:0:0:ffff:1:547

2012-06-27 08:47:57,543 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - MessageType=Relay-Forward

2012-06-27 08:47:57,543 [New I/O datagram worker #2'-'1] DEBUG message.DhcpRelayMessage - HopCount=0

2012-06-27 08:47:57,543 [New I/O datagram worker #2'-'1] DEBUG message.DhcpRelayMessage - LinkAddress: /2001:4408:5220:27:0:0:0:1

2012-06-27 08:47:57,543 [New I/O datagram worker #2'-'1] DEBUG message.DhcpRelayMessage - PeerAddress: /fe80:0:0:0:8c57:d94a:af24:3ec1

2012-06-27 08:47:57,543 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Option code=9

2012-06-27 08:47:57,543 [New I/O datagram worker #2'-'1] DEBUG base.BaseDhcpOption - Relay Message reports length=87:  bytes remaining in buffer=121

2012-06-27 08:47:57,543 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Decoding packet: size=87 localAddr=2001:4408:5220:27:0:0:0:1:547 remoteAddr=fe80:0:0:0:8c57:d94a:af24:3ec1:0

2012-06-27 08:47:57,543 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Message type byte=1

2012-06-27 08:47:57,543 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Decoding DhcpMessage from: fe80:0:0:0:8c57:d94a:af24:3ec1:0

2012-06-27 08:47:57,543 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - MessageType=Solicit

2012-06-27 08:47:57,543 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - TransactionId=14069194

2012-06-27 08:47:57,543 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Option code=8

2012-06-27 08:47:57,543 [New I/O datagram worker #2'-'1] DEBUG base.BaseDhcpOption - DhcpElapsedTimeOption reports length=2:  bytes remaining in buffer=79

2012-06-27 08:47:57,543 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Option code=1

2012-06-27 08:47:57,543 [New I/O datagram worker #2'-'1] DEBUG base.BaseDhcpOption - DhcpClientIdOption reports length=14:  bytes remaining in buffer=73

2012-06-27 08:47:57,544 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Option code=3

2012-06-27 08:47:57,544 [New I/O datagram worker #2'-'1] DEBUG option.DhcpIaNaOption - IA_NA option reports length=12:  bytes remaining in buffer=55

2012-06-27 08:47:57,544 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Option code=39

2012-06-27 08:47:57,544 [New I/O datagram worker #2'-'1] DEBUG base.BaseDhcpOption - DhcpClientFqdnOption reports length=9:  bytes remaining in buffer=39

2012-06-27 08:47:57,544 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Option code=16

2012-06-27 08:47:57,544 [New I/O datagram worker #2'-'1] DEBUG base.BaseDhcpOption - DhcpVendorClassOption reports length=14:  bytes remaining in buffer=26

2012-06-27 08:47:57,544 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Option code=6

2012-06-27 08:47:57,544 [New I/O datagram worker #2'-'1] DEBUG base.BaseDhcpOption - DhcpOptionRequestOption reports length=8:  bytes remaining in buffer=8

2012-06-27 08:47:57,545 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - DhcpMessage decoded.

2012-06-27 08:47:57,545 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Option code=18

2012-06-27 08:47:57,545 [New I/O datagram worker #2'-'1] DEBUG base.BaseDhcpOption - DhcpInterfaceIdOption reports length=4:  bytes remaining in buffer=30

2012-06-27 08:47:57,545 [New I/O datagram worker #2'-'1] DEBUG message.DhcpMessage - Option code=37

2012-06-27 08:47:57,545 [New I/O datagram worker #2'-'1] DEBUG base.BaseDhcpOption - DhcpRemoteIdOption reports length=22:  bytes remaining in buffer=22

2012-06-27 08:47:57,546 [pool-3-thread-2515] WARN  channel.SimpleChannelHandler - EXCEPTION, please implement com.jagornet.dhcpv6.server.netty.DhcpChannelHandler.exceptionCaught() for proper handling.

java.nio.BufferUnderflowException

        at java.nio.HeapByteBuffer.get(HeapByteBuffer.java:145)

        at java.nio.ByteBuffer.get(ByteBuffer.java:692)

        at com.jagornet.dhcpv6.option.OpaqueDataUtil.decodeDataOnly(OpaqueDataUtil.java:191)

        at com.jagornet.dhcpv6.option.DhcpRemoteIdOption.decode(DhcpRemoteIdOption.java:105)

        at com.jagornet.dhcpv6.message.DhcpMessage.decodeOptions(DhcpMessage.java:364)

        at com.jagornet.dhcpv6.message.DhcpRelayMessage.decode(DhcpRelayMessage.java:204)

        at com.jagornet.dhcpv6.message.DhcpMessage.decode(DhcpMessage.java:271)

        at com.jagornet.dhcpv6.server.netty.DhcpChannelDecoder.decode(DhcpChannelDecoder.java:76)

        at com.jagornet.dhcpv6.server.netty.DhcpUnicastChannelDecoder.decode(DhcpUnicastChannelDecoder.java:57)

        at org.jboss.netty.handler.codec.oneone.OneToOneDecoder.handleUpstream(OneToOneDecoder.java:67)

        at com.jagornet.dhcpv6.server.netty.DhcpChannelDecoder.handleUpstream(DhcpChannelDecoder.java:95)

        at org.jboss.netty.handler.logging.LoggingHandler.handleUpstream(LoggingHandler.java:226)

        at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268)

        at org.jboss.netty.channel.socket.nio.NioDatagramWorker.read(NioDatagramWorker.java:413)

        at org.jboss.netty.channel.socket.nio.NioDatagramWorker.processSelectedKeys(NioDatagramWorker.java:342)

        at org.jboss.netty.channel.socket.nio.NioDatagramWorker.run(NioDatagramWorker.java:255)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)

        at java.lang.Thread.run(Thread.java:679)

-- 

Thanks & Regards,

Amit Kumar,
Scientific Officer/ Scientist-SB
Ministry of Communications & Information Technology
Department of Information Technology
National Informatics Center
http://home.nic.in/

Mob: 9910611621 

To view this discussion on the web visit https://groups.google.com/d/msg/jagornet-dhcpv6-users/-/opMyuoAmaFQJ.

To post to this group, send email to jagornet-d...@googlegroups.com.
To unsubscribe from this group, send email to jagornet-dhcpv6-...@googlegroups.com.

[Greg Rabil]

Hi Amit,

This looks like the original Issue 14, which you reported.  Is this log from the server you are running from source?  The line numbers in the stack trace indicate that this is the unfixed code.

Greg

--

You received this message because you are subscribed to the Google Groups "jagornet-dhcpv6-users" group.

To view this discussion on the web visit https://groups.google.com/d/msg/jagornet-dhcpv6-users/-/opMyuoAmaFQJ.

[Amit Kumar]

Hi Greg,

Yes I am running from source...

Thanks 

Amit

To view this discussion on the web visit https://groups.google.com/d/msg/jagornet-dhcpv6-users/-/ubve7d6d3AAJ.

To post to this group, send email to jagornet-d...@googlegroups.com.
To unsubscribe from this group, send email to jagornet-dhcpv6-...@googlegroups.com.

For more options, visit this group at http://groups.google.com/group/jagornet-dhcpv6-users?hl=en.

[Greg Rabil]

Hi Amit,

The stack track below cannot be from the latest source:

com.jagornet.dhcpv6.server.netty.DhcpChannelHandler.exceptionCaught() for proper handling.

        at java.nio.HeapByteBuffer.get(HeapByteBuffer.java:145)

        at java.nio.ByteBuffer.get(ByteBuffer.java:692)

        at com.jagornet.dhcpv6.option.OpaqueDataUtil.decodeDataOnly(OpaqueDataUtil.java:191)

        at com.jagornet.dhcpv6.option.DhcpRemoteIdOption.decode(DhcpRemoteIdOption.java:105)

Line 105 in the DhcpRemoteIdOption class no longer contains any executable code.  That is the line, however, in the version which contained the bug in Issue 14.

Regards,

Greg

Amit

Greg

2012-06-27 08:47:57,546 [pool-3-thread-2515] WARN  channel.SimpleChannelHandler - EXCEPTION, please implementjava.nio.BufferUnderflowException

com.jagornet.dhcpv6.server.netty.DhcpChannelHandler.exceptionCaught() for proper handling.

[Amit Kumar]

Hi Greg,

You mean to say dhcpv6 is not running from latest source.
I actually downloaded the source by running following command:

svn checkout http://jagornet-dhcpv6.googlecode.com/svn/dhcpv6/trunk/ jagornet

and then running jagornet server from jagornet/DHCPv6/bin/dhcpv6 start -m eth0

Is it the right way??

--
Thanks & Regards,

Amit Kumar,
Scientific Officer/ Scientist-SB
Ministry of Communications & Information Technology
Department of Information Technology
National Informatics Center
http://home.nic.in/

Mob: 9910611621

[Greg Rabil]

Hi Amit,

I'm afraid that there is much more to building and running the server from the latest source.  You will need another release to resolve the issue with the remote id option on relayed requests.

Greg

[Amit Kumar]

Hi Greg,

Do I need to wait for next release then.

-- 
Thanks & Regards,

Amit Kumar,
Scientific Officer/ Scientist-SB
Ministry of Communications & Information Technology
Department of Information Technology
National Informatics Center
http://home.nic.in/

Mob: 9910611621 

[Greg Rabil]

Hi Amit,

You will need a new release to get the fix for the RemoteID option problem.  You may workaround that issue if you can configure your DHCPv6 relay agent to NOT send the RemoteID option.

Regards,

Greg

[Amit Kumar]

Hi Greg,

Thanks for the support. I am waiting for the next release. Meanwhile I am just checking how can I disable such option at relay agent. 

Actually I am relaying the dhcpv6 packets through cisco ASR 1002 router.

-- 
Thanks & Regards,

Amit Kumar,
Scientific Officer/ Scientist-SB
Ministry of Communications & Information Technology
Department of Information Technology
National Informatics Center
http://home.nic.in/

Mob: 9910611621