ICMPMonitor packet-size and allow-fragmentation problem.
Description
I'm trying to configure the ICMPMonitor to not fragment and send a larger packet size, but I'm not getting the results expected. Its almost like the "allow-fragmentation" settings are not having any affect. I've configured the following within poller-configuration.xml (taken from the admin guide).
My two test devices (opennms server and a client) are both running 1500 MTU, so I'd expect this configuration to show ICMP as "Down" for the client. However, in the poller.log and opennms I'm seeing ICMP return as "UP".
I thought it might be linked to NMS-8617, but I've configured jnapinger within opennms.properties and still see the issue. Below is a snippet from poller.log for ICMPMonitor using JnaPinger... It looks to be missing the allow-fragmentation parameter?
I've tried this on both 19.0.1 and 20.0.0 and get the same result.
2017-06-24 00:15:39,432 DEBUG [Poller-Thread-1-of-30] o.o.n.p.p.PollableServiceConfig: Polling PollableService[location=Default, interface=PollableInterface [PollableNode [1]:10.43.12.50], svcName=ICMP] with TTL 300000 using pkg example1 2017-06-24 00:15:39,459 DEBUG [pool-9-thread-1] o.o.j.j.NativeDatagramSocket: org.opennms.jicmp.jna.UnixV4NativeSocket(2, 1, 23098) 2017-06-24 00:15:39,460 DEBUG [pool-9-thread-1] o.o.j.j.NativeDatagramSocket: org.opennms.jicmp.jna.UnixV6NativeSocket(10, 58, 23098) 2017-06-24 00:15:39,502 DEBUG [pool-9-thread-1] o.o.n.i.j.JnaPingRequest: 1498259739502: Sending Ping Request: [ID=JnaPingRequestId[addr = /10.43.12.50, ident = 23098, seqNum = 1, tId = 1],Retries=2,Timeout=3000,Packet-Size=2048,Expirati on=-1,Callback=org.opennms.netmgt.icmp.LogPrefixPreservingPingResponseCallback@3d71a279] 2017-06-24 00:15:39,528 DEBUG [pool-9-thread-1] o.o.p.r.RequestTracker: Scheding timeout for request to [ID=JnaPingRequestId[addr = /10.43.12.50, ident = 23098, seqNum = 1, tId = 1],Retries=2,Timeout=3000,Packet-Size=2048,Expiration=1498 259742503,Callback=org.opennms.netmgt.icmp.LogPrefixPreservingPingResponseCallback@3d71a279] in 2975 ms 2017-06-24 00:15:39,529 INFO [pool-9-thread-1] o.o.n.i.SinglePingResponseCallback: waiting for ping to /10.43.12.50 to finish 2017-06-24 00:15:39,529 INFO [JNA-ICMP-23098-Callback-Processor] o.o.n.i.SinglePingResponseCallback: got response for address /10.43.12.50, thread 23098, seq 1 with a responseTime 2.634982ms 2017-06-24 00:15:39,532 INFO [pool-9-thread-1] o.o.n.i.SinglePingResponseCallback: finished waiting for ping to /10.43.12.50 to finish 2017-06-24 00:15:39,532 DEBUG [pool-9-thread-1] o.o.n.p.p.LatencyStoringServiceMonitorAdaptor: storeResponseTime: Thresholds processing is not enabled. Check thresholding-enabled parameter on service definition 2017-06-24 00:15:39,532 DEBUG [pool-9-thread-1] o.o.n.p.p.LatencyStoringServiceMonitorAdaptor: storeResponseTime: Persisting latency data for PollableService[location=Default, interface=PollableInterface [PollableNode [1]:10.43.12.50], s vcName=ICMP] 2017-06-24 00:15:39,570 INFO [pool-9-thread-1] o.o.n.c.a.AbstractPersister: Persisting data for resource ICMP on 10.43.12.50 at Default 2017-06-24 00:15:39,570 DEBUG [pool-9-thread-1] o.o.n.c.a.AttributeGroup: Visiting Group AttrGroupType[name=icmp, ifType=all] for 10.43.12.50[ICMP]@10.43.12.50 2017-06-24 00:15:39,591 DEBUG [pool-9-thread-1] o.o.n.c.a.AttributeGroup: AttrGroupType[name=icmp, ifType=all] for 10.43.12.50[ICMP]@10.43.12.50.shouldPersist = true 2017-06-24 00:15:39,614 DEBUG [pool-9-thread-1] o.o.n.p.LatencyCollectionAttribute: Visiting attribute icmp: 2635.000000 2017-06-24 00:15:39,620 DEBUG [pool-9-thread-1] o.o.n.c.a.AbstractPersister: Persisting icmp: 2635.000000 2017-06-24 00:15:39,620 DEBUG [pool-9-thread-1] o.o.n.c.a.AbstractPersister: Storing attribute icmp: 2635.000000 2017-06-24 00:15:39,623 INFO [pool-9-thread-1] o.o.n.r.RrdMetaDataUtils: createMetaDataFile: creating meta data file /var/lib/opennms/rrd/response/10.43.12.50/icmp.meta with values '{ICMP/10.43.12.50=icmp}' 2017-06-24 00:15:39,640 DEBUG [pool-9-thread-1] o.o.n.r.j.JRobinRrdStrategy: createDefinition: filename /var/lib/opennms/rrd/response/10.43.12.50/icmp.jrb already exists returning null as definition 2017-06-24 00:15:39,641 DEBUG [pool-9-thread-1] o.o.n.r.j.JRobinRrdStrategy: createRRD: skipping RRD file 2017-06-24 00:15:39,648 INFO [pool-9-thread-1] o.o.n.c.p.r.RrdPersistOperationBuilder: updateRRD: updating RRD file /var/lib/opennms/rrd/response/10.43.12.50/icmp.jrb with values '1498259740:2635' 2017-06-24 00:15:39,649 DEBUG [pool-9-thread-1] o.o.n.c.p.r.RrdPersistOperationBuilder: updateRRD: RRD update command completed. 2017-06-24 00:15:39,649 DEBUG [Poller-Thread-1-of-30] o.o.n.p.p.PollableServiceConfig: Finish polling PollableService[location=Default, interface=PollableInterface [PollableNode [1]:10.43.12.50], svcName=ICMP] using pkg example1 result = Up 2017-06-24 00:15:39,650 DEBUG [Poller-Thread-1-of-30] o.o.n.p.p.PollableService: Finish Scheduled Poll of service PollableService[location=Default, interface=PollableInterface [PollableNode [1]:10.43.12.50], svcName=ICMP], started at 201 7-06-24T00:15:39.411+0100 2017-06-24 00:15:39,650 DEBUG [Poller-Thread-1-of-30] o.o.n.s.LegacyScheduler: schedule: Adding ready runnable ScheduleEntry[expCode=1] for PollableService[location=Default, interface=PollableInterface [PollableNode [1]:10.43.12.50], svc Name=ICMP] (ready in 300000ms) at interval 300000
Its probably something I'm configuring incorrectly or misunderstanding... Any help would be much appreciated as I'd really like to start using this feature.
----EDIT------------
I've used tshark to have a look at the packet (suggestion from indigo). It looks like the packet is fragmenting and ignoring the "allow-fragmentation" parameter.
tshark output -------------------
1 0.000000000 10.1.1.1 â 10.2.2.2 IPv4 1514 Fragmented IP protocol (proto=ICMP 1, off=0, ID=4ab1) 2 0.000090502 10.1.1.1 â 10.2.2.2 ICMP 602 Echo (ping) request id=0x21a2, seq=1/256, ttl=64 3 0.000814279 10.2.2.2 â 10.1.1.1 IPv4 1514 Fragmented IP protocol (proto=ICMP 1, off=0, ID=b510) 4 0.000819198 10.2.2.2 â 10.1.1.1 ICMP 602 Echo (ping) reply id=0x21a2, seq=1/256, ttl=60 (request in 2)
Environment
Ubuntu 16.04.2
Opennms 20.0.0
Acceptance / Success Criteria
None
Lucidchart Diagrams
Activity
Show:
Paul Ronald June 26, 2017 at 5:18 PM
I'm seeing something else a bit strange with regards to the "packet-size" parameter. Which part of the packet is this parameter referring? i.e. IP Header + ICMP Header + Payload etc
On a device that has an MTU of 1500 set on the NIC the maximum "packet-size" parameter I can specify before fragmentation begins is 1488. If it was just referring to payload I'd have thought setting the "packet-size" parameter to 1472 would have been the maximum. (Ethernet=14,IP Header=20,ICMP Header=8,Payload=1472).
Below is a tshark capture with "packet-size" set to 1488:
Jesse White June 26, 2017 at 4:35 PM
I can confirm something is not right here. Using ping from a shell I get:
Running the IcmpMonitor from a Karaf shell I get:
and tcpdump confirms the ICMP requests/reply packets we in fact fragmented when using the IcmpMonitor.
Paul Ronald June 26, 2017 at 4:08 PM
So after some more testing with wireshark the "allow-fragmentation" settings are working perfectly... I can see that the "dont fragment" flag is being set.
I'm trying to configure the ICMPMonitor to not fragment and send a larger packet size, but I'm not getting the results expected. Its almost like the "allow-fragmentation" settings are not having any affect. I've configured the following within poller-configuration.xml (taken from the admin guide).
<service name="ICMP" interval="300000" user-defined="false" status="on">
<parameter key="retry" value="2"/>
<parameter key="timeout" value="3000"/>
<parameter key="allow-fragmentation" value="false"/>
<parameter key="packet-size" value="2048"/>
<parameter key="rrd-repository" value="/var/lib/opennms/rrd/response"/>
<parameter key="rrd-base-name" value="icmp"/>
<parameter key="ds-name" value="icmp"/>
</service>
<monitor service="ICMP" class-name="org.opennms.netmgt.poller.monitors.IcmpMonitor"/>
My two test devices (opennms server and a client) are both running 1500 MTU, so I'd expect this configuration to show ICMP as "Down" for the client. However, in the poller.log and opennms I'm seeing ICMP return as "UP".
I thought it might be linked to NMS-8617, but I've configured jnapinger within opennms.properties and still see the issue. Below is a snippet from poller.log for ICMPMonitor using JnaPinger... It looks to be missing the allow-fragmentation parameter?
I've tried this on both 19.0.1 and 20.0.0 and get the same result.
2017-06-24 00:15:39,432 DEBUG [Poller-Thread-1-of-30] o.o.n.p.p.PollableServiceConfig: Polling PollableService[location=Default, interface=PollableInterface [PollableNode [1]:10.43.12.50], svcName=ICMP] with TTL 300000 using pkg example1
2017-06-24 00:15:39,459 DEBUG [pool-9-thread-1] o.o.j.j.NativeDatagramSocket: org.opennms.jicmp.jna.UnixV4NativeSocket(2, 1, 23098)
2017-06-24 00:15:39,460 DEBUG [pool-9-thread-1] o.o.j.j.NativeDatagramSocket: org.opennms.jicmp.jna.UnixV6NativeSocket(10, 58, 23098)
2017-06-24 00:15:39,502 DEBUG [pool-9-thread-1] o.o.n.i.j.JnaPingRequest: 1498259739502: Sending Ping Request: [ID=JnaPingRequestId[addr = /10.43.12.50, ident = 23098, seqNum = 1, tId = 1],Retries=2,Timeout=3000,Packet-Size=2048,Expirati
on=-1,Callback=org.opennms.netmgt.icmp.LogPrefixPreservingPingResponseCallback@3d71a279]
2017-06-24 00:15:39,528 DEBUG [pool-9-thread-1] o.o.p.r.RequestTracker: Scheding timeout for request to [ID=JnaPingRequestId[addr = /10.43.12.50, ident = 23098, seqNum = 1, tId = 1],Retries=2,Timeout=3000,Packet-Size=2048,Expiration=1498
259742503,Callback=org.opennms.netmgt.icmp.LogPrefixPreservingPingResponseCallback@3d71a279] in 2975 ms
2017-06-24 00:15:39,529 INFO [pool-9-thread-1] o.o.n.i.SinglePingResponseCallback: waiting for ping to /10.43.12.50 to finish
2017-06-24 00:15:39,529 INFO [JNA-ICMP-23098-Callback-Processor] o.o.n.i.SinglePingResponseCallback: got response for address /10.43.12.50, thread 23098, seq 1 with a responseTime 2.634982ms
2017-06-24 00:15:39,532 INFO [pool-9-thread-1] o.o.n.i.SinglePingResponseCallback: finished waiting for ping to /10.43.12.50 to finish
2017-06-24 00:15:39,532 DEBUG [pool-9-thread-1] o.o.n.p.p.LatencyStoringServiceMonitorAdaptor: storeResponseTime: Thresholds processing is not enabled. Check thresholding-enabled parameter on service definition
2017-06-24 00:15:39,532 DEBUG [pool-9-thread-1] o.o.n.p.p.LatencyStoringServiceMonitorAdaptor: storeResponseTime: Persisting latency data for PollableService[location=Default, interface=PollableInterface [PollableNode [1]:10.43.12.50], s
vcName=ICMP]
2017-06-24 00:15:39,570 INFO [pool-9-thread-1] o.o.n.c.a.AbstractPersister: Persisting data for resource ICMP on 10.43.12.50 at Default
2017-06-24 00:15:39,570 DEBUG [pool-9-thread-1] o.o.n.c.a.AttributeGroup: Visiting Group AttrGroupType[name=icmp, ifType=all] for 10.43.12.50[ICMP]@10.43.12.50
2017-06-24 00:15:39,591 DEBUG [pool-9-thread-1] o.o.n.c.a.AttributeGroup: AttrGroupType[name=icmp, ifType=all] for 10.43.12.50[ICMP]@10.43.12.50.shouldPersist = true
2017-06-24 00:15:39,614 DEBUG [pool-9-thread-1] o.o.n.p.LatencyCollectionAttribute: Visiting attribute icmp: 2635.000000
2017-06-24 00:15:39,620 DEBUG [pool-9-thread-1] o.o.n.c.a.AbstractPersister: Persisting icmp: 2635.000000
2017-06-24 00:15:39,620 DEBUG [pool-9-thread-1] o.o.n.c.a.AbstractPersister: Storing attribute icmp: 2635.000000
2017-06-24 00:15:39,623 INFO [pool-9-thread-1] o.o.n.r.RrdMetaDataUtils: createMetaDataFile: creating meta data file /var/lib/opennms/rrd/response/10.43.12.50/icmp.meta with values '{ICMP/10.43.12.50=icmp}'
2017-06-24 00:15:39,640 DEBUG [pool-9-thread-1] o.o.n.r.j.JRobinRrdStrategy: createDefinition: filename /var/lib/opennms/rrd/response/10.43.12.50/icmp.jrb already exists returning null as definition
2017-06-24 00:15:39,641 DEBUG [pool-9-thread-1] o.o.n.r.j.JRobinRrdStrategy: createRRD: skipping RRD file
2017-06-24 00:15:39,648 INFO [pool-9-thread-1] o.o.n.c.p.r.RrdPersistOperationBuilder: updateRRD: updating RRD file /var/lib/opennms/rrd/response/10.43.12.50/icmp.jrb with values '1498259740:2635'
2017-06-24 00:15:39,649 DEBUG [pool-9-thread-1] o.o.n.c.p.r.RrdPersistOperationBuilder: updateRRD: RRD update command completed.
2017-06-24 00:15:39,649 DEBUG [Poller-Thread-1-of-30] o.o.n.p.p.PollableServiceConfig: Finish polling PollableService[location=Default, interface=PollableInterface [PollableNode [1]:10.43.12.50], svcName=ICMP] using pkg example1 result =
Up
2017-06-24 00:15:39,650 DEBUG [Poller-Thread-1-of-30] o.o.n.p.p.PollableService: Finish Scheduled Poll of service PollableService[location=Default, interface=PollableInterface [PollableNode [1]:10.43.12.50], svcName=ICMP], started at 201
7-06-24T00:15:39.411+0100
2017-06-24 00:15:39,650 DEBUG [Poller-Thread-1-of-30] o.o.n.s.LegacyScheduler: schedule: Adding ready runnable ScheduleEntry[expCode=1] for PollableService[location=Default, interface=PollableInterface [PollableNode [1]:10.43.12.50], svc
Name=ICMP] (ready in 300000ms) at interval 300000
Its probably something I'm configuring incorrectly or misunderstanding... Any help would be much appreciated as I'd really like to start using this feature.
----EDIT------------
I've used tshark to have a look at the packet (suggestion from indigo). It looks like the packet is fragmenting and ignoring the "allow-fragmentation" parameter.
tshark output
-------------------
1 0.000000000 10.1.1.1 â 10.2.2.2 IPv4 1514 Fragmented IP protocol (proto=ICMP 1, off=0, ID=4ab1)
2 0.000090502 10.1.1.1 â 10.2.2.2 ICMP 602 Echo (ping) request id=0x21a2, seq=1/256, ttl=64
3 0.000814279 10.2.2.2 â 10.1.1.1 IPv4 1514 Fragmented IP protocol (proto=ICMP 1, off=0, ID=b510)
4 0.000819198 10.2.2.2 â 10.1.1.1 ICMP 602 Echo (ping) reply id=0x21a2, seq=1/256, ttl=60 (request in 2)