Routing
Highlighted
Routing

OSPF adjacency stuck in Exstart state

‎07-26-2017 11:37 AM

I 2 have router connected point to point and configured ospf as follows.

root@R1# show protocols ospf         
traceoptions {
    file ospf-debug size 1g files 5;
    flag all;
}
area 0.0.0.0 {
    interface ge-0/0/0.0;
    interface ge-0/0/1.0;
    interface ae0.0;
    interface lo0.0 {
        passive;
    }
}

root@R1# show interfaces ge-0/0/0  
unit 0 {
    family inet {
        address 172.27.0.1/24;
    }
}
root@R2# show protocols ospf   
traceoptions {
    file ospf-debug size 1g files 5;
    flag all;
}
area 0.0.0.0 {
    interface ge-0/0/0.0;
    interface ge-0/0/1.0;
    interface lo0.0 {
        passive;
    }
}

root@R2# show interfaces ge-0/0/0  
unit 0 {
    family inet {
        address 172.27.0.2/24;
    }
}


root@R1# run show ospf neighbor 
Address          Interface              State     ID               Pri  Dead
172.27.0.9       ae0.0                  Full      172.27.255.4     128    34
172.27.0.2       ge-0/0/0.0             ExStart   172.27.255.2     128    31
172.27.0.13      ge-0/0/1.0             Full      172.27.255.3     128    34

root@R2# run show ospf neighbor 
Address          Interface              State     ID               Pri  Dead
172.27.0.1       ge-0/0/0.0             ExStart   172.27.255.1     128    35
172.27.0.6       ge-0/0/1.0             ExStart   172.27.255.4     128    39

 

Traceoptions logs from R2:

Jul 26 11:16:58.013464 OSPF sent DbD 172.27.0.5 -> 172.27.0.6 (ge-0/0/1.0 IFL 331 area 0.0.0.0)
Jul 26 11:16:58.013471   Version 2, length 32, ID 172.27.255.2, area 0.0.0.0
Jul 26 11:16:58.013477   options 0x52, i 1, m 1, ms 1, r 0, seq 0xac1ae1d0, mtu 1500
Jul 26 11:16:58.013482 OSPF restart signaling: Add LLS data for DbD packet on interface ge-0/0/1.0.
Jul 26 11:16:58.013493 task_timer_uset: timer OSPF I/O./var/run/ppmd_control_PPM Keepalive <Touched> set to offset 40 at 11:17:38.013482
Jul 26 11:16:58.013502 task_timer_reset: reset OSPF_DBD rexmit
Jul 26 11:16:58.013511 task_timer_set_oneshot_latest: timer OSPF_DBD rexmit interval set to 4.721622
Jul 26 11:16:58.063273 task_timer_reset: reset OSPF_Global xmit timer
Jul 26 11:16:58.187729 task_process_events: recv ready for OSPF I/O./var/run/ppmd_control
Jul 26 11:16:58.187770 task_process_events: recv ready for OSPF I/O./var/run/ppmd_control
Jul 26 11:16:58.187796 task_timer_uset: timer OSPF I/O./var/run/ppmd_control_PPM Hold <Touched> set to offset 2:00 at 11:18:58.187770
Jul 26 11:16:58.187811 Received OSPF packet of type and wire_length 2, 44
Jul 26 11:16:58.187824 OSPF rcvd DbD 172.27.0.1 -> 172.27.0.2 (ge-0/0/0.0 IFL 330 area 0.0.0.0)
Jul 26 11:16:58.187831   Version 2, length 32, ID 172.27.255.1, area 0.0.0.0
Jul 26 11:16:58.187841   checksum 0x0, authtype 0
Jul 26 11:16:58.187847   options 0x52, i 1, m 1, ms 1, r 0, seq 0xac1d9684, mtu 1500
Jul 26 11:16:58.187859 task_job_create_background: create prio 1 job OSPF process rcvd dbd packets for task OSPF
Jul 26 11:16:58.187873 background dispatch running job OSPF process rcvd dbd packets for task OSPF
Jul 26 11:16:58.187881 ospf_process_dbd: processing dbd from 172.27.0.1
Jul 26 11:16:58.187889 OSPF restart signaling: Received DBD with LLS data from nbr ip=172.27.0.1 id=172.27.255.1.
Jul 26 11:16:58.187897 ospf_process_dbd: dbd from 172.27.0.1 ignored
Jul 26 11:16:58.187905 task_job_delete: delete background job OSPF process rcvd dbd packets for task OSPF
Jul 26 11:16:58.187913 background dispatch completed job OSPF process rcvd dbd packets for task OSPF
Jul 26 11:16:58.718416 task_process_events: recv ready for OSPF I/O./var/run/ppmd_control
Jul 26 11:16:58.718459 task_process_events: recv ready for OSPF I/O./var/run/ppmd_control
Jul 26 11:16:58.718486 task_timer_uset: timer OSPF I/O./var/run/ppmd_control_PPM Hold <Touched> set to offset 2:00 at 11:18:58.718459
Jul 26 11:16:58.718497 OSPF hello from 172.27.0.1 (IFL 330, area 0.0.0.0) absorbed
Jul 26 11:17:02.448501 task_process_events: recv ready for OSPF I/O./var/run/ppmd_control
Jul 26 11:17:02.448581 task_process_events: recv ready for OSPF I/O./var/run/ppmd_control
Jul 26 11:17:02.448768 task_timer_uset: timer OSPF I/O./var/run/ppmd_control_PPM Hold <Touched> set to offset 2:00 at 11:19:02.448581
Jul 26 11:17:02.448794 Received OSPF packet of type and wire_length 2, 44

Any suggestion would be appreciated.

 

Thanks!!

 

 

10 REPLIES 10
Routing

Re: OSPF adjacency stuck in Exstart state

‎07-26-2017 12:37 PM

Two things generally cause this. Mismatched MTU and firewall filter on loopback interface. I see no mtu mismathced in debug. Check it anyways. Is there a firewall filter on the lo0 interface of R2? Firewall filters are notorious and generally are difficult to figure out they are actually the problem.

add the detail knob

set protocol ospf traceoptions flag all detail

> show ospf statistics

See what types of errors are being generated

[KUDOS PLEASE! If you think I earned it!
If this solution worked for you please flag my post as an "Accepted Solution" so others can benefit..]
Routing

Re: OSPF adjacency stuck in Exstart state

‎07-26-2017 02:04 PM

MTU is same on both side.
No firewall filter configured on lo0
I added the detail knob in traceoption config
Following is the ospf debug on R1

Jul 26 13:59:27.899944 OSPF sent DbD 172.27.0.1 -> 172.27.0.2 (ge-0/0/0.0 IFL 331 area 0.0.0.0)
Jul 26 13:59:27.899949   Version 2, length 32, ID 172.27.255.1, area 0.0.0.0
Jul 26 13:59:27.899954   options 0x52, i 1, m 1, ms 1, r 0, seq 0xac1d9684, mtu 1500
Jul 26 13:59:27.899958 OSPF restart signaling: Add LLS data for DbD packet on interface ge-0/0/0.0.
Jul 26 13:59:27.899971 task_timer_uset: timer OSPF I/O./var/run/ppmd_control_PPM Keepalive <Touched> set to offset 40 at 14:00:07.899958
Jul 26 13:59:27.899982 task_timer_reset: reset OSPF_DBD rexmit
Jul 26 13:59:27.899989 task_timer_set_oneshot_latest: timer OSPF_DBD rexmit interval set to 4.856792
Jul 26 13:59:27.949792 task_timer_reset: reset OSPF_Global xmit timer
Jul 26 13:59:29.276805 task_process_events: recv ready for OSPF I/O./var/run/ppmd_control
Jul 26 13:59:29.276845 task_process_events: recv ready for OSPF I/O./var/run/ppmd_control
Jul 26 13:59:29.276864 task_timer_uset: timer OSPF I/O./var/run/ppmd_control_PPM Hold <Touched> set to offset 2:00 at 14:01:29.276845
Jul 26 13:59:29.276871 OSPF hello from 172.27.0.9 (IFL 330, area 0.0.0.0) absorbed
Jul 26 13:59:29.309829 task_process_events: recv ready for OSPF I/O./var/run/ppmd_control
Jul 26 13:59:29.309858 task_process_events: recv ready for OSPF I/O./var/run/ppmd_control
Jul 26 13:59:29.309873 task_timer_uset: timer OSPF I/O./var/run/ppmd_control_PPM Hold <Touched> set to offset 2:00 at 14:01:29.309858
Jul 26 13:59:29.309879 OSPF periodic xmit from 172.27.0.14 to 224.0.0.5 (IFL 332 area 0.0.0.0)
Jul 26 13:59:30.949851 task_process_events: recv ready for OSPF I/O./var/run/ppmd_control
Jul 26 13:59:30.949891 task_process_events: recv ready for OSPF I/O./var/run/ppmd_control
Jul 26 13:59:30.949904 task_timer_uset: timer OSPF I/O./var/run/ppmd_control_PPM Hold <Touched> set to offset 2:00 at 14:01:30.949891
Jul 26 13:59:30.949910 OSPF periodic xmit from 172.27.0.10 to 224.0.0.5 (IFL 330 area 0.0.0.0)
Jul 26 13:59:31.979878 task_process_events: recv ready for OSPF I/O./var/run/ppmd_control
Jul 26 13:59:31.979918 task_process_events: recv ready for OSPF I/O./var/run/ppmd_control
Jul 26 13:59:31.979932 task_timer_uset: timer OSPF I/O./var/run/ppmd_control_PPM Hold <Touched> set to offset 2:00 at 14:01:31.979918
Jul 26 13:59:31.979938 OSPF periodic xmit from 172.27.0.1 to 224.0.0.5 (IFL 331 area 0.0.0.0)
Jul 26 13:59:32.770055 OSPF resend last DBD to 172.27.0.2
Jul 26 13:59:32.770116 task_timer_uset: timer OSPF_Global xmit timer <Touched> set to interval 0.040000 jitter 10 at 13:59:32.806665
Jul 26 13:59:32.770122 task_timer_expire_immediately: timer OSPF_Global xmit timer set to expire now
Jul 26 13:59:32.770126 OSPF retransmitting DBD to 172.27.0.2
Jul 26 13:59:32.770138 OSPF sent DbD 172.27.0.1 -> 172.27.0.2 (ge-0/0/0.0 IFL 331 area 0.0.0.0)
Jul 26 13:59:32.770154   Version 2, length 32, ID 172.27.255.1, area 0.0.0.0
Jul 26 13:59:32.770159   options 0x52, i 1, m 1, ms 1, r 0, seq 0xac1d9684, mtu 1500
Jul 26 13:59:32.770176 OSPF restart signaling: Add LLS data for DbD packet on interface ge-0/0/0.0.
Jul 26 13:59:32.770188 task_timer_uset: timer OSPF I/O./var/run/ppmd_control_PPM Keepalive <Touched> set to offset 40 at 14:00:12.770176
Jul 26 13:59:32.770198 task_timer_reset: reset OSPF_DBD rexmit
Jul 26 13:59:32.770205 task_timer_set_oneshot_latest: timer OSPF_DBD rexmit interval set to 4.743509
Jul 26 13:59:32.819860 task_timer_reset: reset OSPF_Global xmit timer
Jul 26 13:59:34.195544 task_process_events: recv ready for OSPF I/O./var/run/ppmd_control
Jul 26 13:59:34.195594 task_process_events: recv ready for OSPF I/O./var/run/ppmd_control
Jul 26 13:59:34.195611 task_timer_uset: timer OSPF I/O./var/run/ppmd_control_PPM Hold <Touched> set to offset 2:00 at 14:01:34.195594
Jul 26 13:59:34.195629 OSPF hello from 172.27.0.2 (IFL 331, area 0.0.0.0) absorbed
Jul 26 13:59:34.397400 task_process_events: recv ready for OSPF I/O./var/run/ppmd_control
Jul 26 13:59:34.397424 task_process_events: recv ready for OSPF I/O./var/run/ppmd_control
Jul 26 13:59:34.397439 task_timer_uset: timer OSPF I/O./var/run/ppmd_control_PPM Hold <Touched> set to offset 2:00 at 14:01:34.397424
Jul 26 13:59:34.397445 OSPF hello from 172.27.0.13 (IFL 332, area 0.0.0.0) absorbed
Jul 26 13:59:37.529846 OSPF resend last DBD to 172.27.0.2
Jul 26 13:59:37.529888 task_timer_uset: timer OSPF_Global xmit timer <Touched> set to interval 0.040000 jitter 10 at 13:59:37.567302
Jul 26 13:59:37.529894 task_timer_expire_immediately: timer OSPF_Global xmit timer set to expire now
Jul 26 13:59:37.529899 OSPF retransmitting DBD to 172.27.0.2
root@R1# run show ospf statistics 

Packet type             Total                  Last 5 seconds
                   Sent      Received        Sent      Received
   Hello           3947          3779           2             3
     DbD           2561             4           1             0
   LSReq              2             2           0             0
LSUpdate             41            22           0             0
   LSAck             21            37           0             0

DBDs retransmitted     :                 2554, last 5 seconds :          1
LSAs flooded           :                   33, last 5 seconds :          0
LSAs flooded high-prio :                   13, last 5 seconds :          0
LSAs retransmitted     :                    0, last 5 seconds :          0
LSAs transmitted to nbr:                    4, last 5 seconds :          0
LSAs requested         :                    2, last 5 seconds :          0
LSAs acknowledged      :                   26, last 5 seconds :          0

Flood queue depth      :               0
Total rexmit entries   :               0
db summaries           :               0
lsreq entries          :               0

Receive errors:
  None


root@R2# run show ospf statistics 

Packet type             Total                  Last 5 seconds
                   Sent      Received        Sent      Received
   Hello           2604          2528           1             1
     DbD           4998           984           2             0
   LSReq              0             0           0             0
LSUpdate              0             0           0             0
   LSAck              0             0           0             0

DBDs retransmitted     :                 4996, last 5 seconds :          2
LSAs flooded           :                    0, last 5 seconds :          0
LSAs flooded high-prio :                    0, last 5 seconds :          0
LSAs retransmitted     :                    0, last 5 seconds :          0
LSAs transmitted to nbr:                    0, last 5 seconds :          0
LSAs requested         :                    0, last 5 seconds :          0
LSAs acknowledged      :                    0, last 5 seconds :          0

Flood queue depth      :               0
Total rexmit entries   :               0
db summaries           :               0
lsreq entries          :               0

Receive errors:
  None

Thanks!!

Routing

Re: OSPF adjacency stuck in Exstart state

‎07-26-2017 02:15 PM

No errors seen. R1 reports absorbed, meaning no problems now, we all copasetic. Weird! Enable traceoptions on R2. Same configuration options and post that result.

[KUDOS PLEASE! If you think I earned it!
If this solution worked for you please flag my post as an "Accepted Solution" so others can benefit..]
Routing

Re: OSPF adjacency stuck in Exstart state

‎07-26-2017 02:25 PM

Logs on R2 :

Jul 26 14:24:24.844587 OSPF sent DbD 172.27.0.2 -> 172.27.0.1 (ge-0/0/0.0 IFL 330 area 0.0.0.0)
Jul 26 14:24:24.844614   Version 2, length 32, ID 172.27.255.2, area 0.0.0.0
Jul 26 14:24:24.844621   options 0x52, i 1, m 1, ms 1, r 0, seq 0xac1e0b8c, mtu 1500
Jul 26 14:24:24.844628 OSPF restart signaling: Add LLS data for DbD packet on interface ge-0/0/0.0.
Jul 26 14:24:24.844644 task_timer_uset: timer OSPF I/O./var/run/ppmd_control_PPM Keepalive <Touched> set to offset 40 at 14:25:04.844628
Jul 26 14:24:24.844661 task_timer_reset: reset OSPF_DBD rexmit
Jul 26 14:24:24.844671 task_timer_set_oneshot_latest: timer OSPF_DBD rexmit interval set to 4.959995
Jul 26 14:24:24.844683 OSPF sent DbD 172.27.0.5 -> 172.27.0.6 (ge-0/0/1.0 IFL 331 area 0.0.0.0)
Jul 26 14:24:24.844690   Version 2, length 32, ID 172.27.255.2, area 0.0.0.0
Jul 26 14:24:24.844696   options 0x52, i 1, m 1, ms 1, r 0, seq 0xac1ae1d0, mtu 1500
Jul 26 14:24:24.844702 OSPF restart signaling: Add LLS data for DbD packet on interface ge-0/0/1.0.
Jul 26 14:24:24.844714 task_timer_uset: timer OSPF I/O./var/run/ppmd_control_PPM Keepalive <Touched> set to offset 40 at 14:25:04.844702
Jul 26 14:24:24.844723 task_timer_reset: reset OSPF_DBD rexmit
Jul 26 14:24:24.844732 task_timer_set_oneshot_latest: timer OSPF_DBD rexmit interval set to 4.959996
Jul 26 14:24:24.894461 task_timer_reset: reset OSPF_Global xmit timer
Jul 26 14:24:24.964526 task_process_events: recv ready for OSPF I/O./var/run/ppmd_control
Jul 26 14:24:24.964557 task_process_events: recv ready for OSPF I/O./var/run/ppmd_control
Jul 26 14:24:24.964582 task_timer_uset: timer OSPF I/O./var/run/ppmd_control_PPM Hold <Touched> set to offset 2:00 at 14:26:24.964557
Jul 26 14:24:24.964592 OSPF periodic xmit from 172.27.0.2 to 224.0.0.5 (IFL 330 area 0.0.0.0)
Jul 26 14:24:27.194373 task_process_events: recv ready for OSPF I/O./var/run/ppmd_control
Jul 26 14:24:27.194479 task_process_events: recv ready for OSPF I/O./var/run/ppmd_control
Jul 26 14:24:27.194507 task_timer_uset: timer OSPF I/O./var/run/ppmd_control_PPM Hold <Touched> set to offset 2:00 at 14:26:27.194479
Jul 26 14:24:27.194518 OSPF hello from 172.27.0.1 (IFL 330, area 0.0.0.0) absorbed
Jul 26 14:24:29.814482 OSPF resend last DBD to 172.27.0.1
Jul 26 14:24:29.814563 task_timer_uset: timer OSPF_Global xmit timer <Touched> set to interval 0.040000 jitter 10 at 14:24:29.851216
Jul 26 14:24:29.814572 task_timer_expire_immediately: timer OSPF_Global xmit timer set to expire now
Jul 26 14:24:29.814580 OSPF retransmitting DBD to 172.27.0.1
Jul 26 14:24:29.814589 OSPF resend last DBD to 172.27.0.6
Jul 26 14:24:29.814596 OSPF retransmitting DBD to 172.27.0.6
Jul 26 14:24:29.814613 OSPF sent DbD 172.27.0.2 -> 172.27.0.1 (ge-0/0/0.0 IFL 330 area 0.0.0.0)
Jul 26 14:24:29.814621   Version 2, length 32, ID 172.27.255.2, area 0.0.0.0
Jul 26 14:24:29.814629   options 0x52, i 1, m 1, ms 1, r 0, seq 0xac1e0b8c, mtu 1500
Jul 26 14:24:29.814635 OSPF restart signaling: Add LLS data for DbD packet on interface ge-0/0/0.0.
Jul 26 14:24:29.814654 task_timer_uset: timer OSPF I/O./var/run/ppmd_control_PPM Keepalive <Touched> set to offset 40 at 14:25:09.814635
Jul 26 14:24:29.814677 task_timer_reset: reset OSPF_DBD rexmit
Jul 26 14:24:29.814687 task_timer_set_oneshot_latest: timer OSPF_DBD rexmit interval set to 4.517824
Routing

Re: OSPF adjacency stuck in Exstart state

‎07-26-2017 02:39 PM

Even more weird. No errors and the logs say the adjacency is successful. Is is possible to to restart R2? Can you deactivate ospf on R2, commit the config, wait a few minutes, then activate ospf, but enter "commit full". As you can see these are disruptive, so some downtime will need to be scheduled.

[KUDOS PLEASE! If you think I earned it!
If this solution worked for you please flag my post as an "Accepted Solution" so others can benefit..]
Routing

Re: OSPF adjacency stuck in Exstart state

‎07-26-2017 03:08 PM

i'm running this topology on Junosphere for certification purpose and seen this weird issue.
I tried deactivate (wait few minute) and activate ospf on R2 but didn't help. I tried on same on R1 as well but no change.

Routing

Re: OSPF adjacency stuck in Exstart state

‎07-26-2017 03:55 PM

Okay. It is still weird, primarily because no erros are logged and the "absorbed" means established full or 2-way if between non-BDR/DRF ospf routers. Well delete the ospf config on both devices, reboot them then reconfigure it again. If the problem persists, then it could be a bug in the Junosphere environment and you probably should open a ticket with Juniper.

[KUDOS PLEASE! If you think I earned it!
If this solution worked for you please flag my post as an "Accepted Solution" so others can benefit..]
Routing

Re: OSPF adjacency stuck in Exstart state

‎07-26-2017 08:36 PM

I was under the impression that multiple interfaces in the same subnet causes packet loss and other oddities.

 

https://kb.juniper.net/InfoCenter/index?page=content&id=KB24928&actp=METADATA

Routing
Solution
Accepted by topic author Jay040
‎07-27-2017 11:04 AM

Re: OSPF adjacency stuck in Exstart state

‎07-27-2017 02:19 AM

HI, 

 

What if you add interface-type p2p to the ospf configuration.

 

Abdellah HAMDAD
Senior Network Consultant
JNCIE-SP/ENT/SEC
JNCIP-DC
JNCSP-SP/ENT/SEC
JNCDS-WAN/DC/SEC
Routing

Re: OSPF adjacency stuck in Exstart state

[ Edited ]
‎07-27-2017 11:02 AM

Changing interface type to p2p worked..

 

root@R1# run show ospf neighbor
Address          Interface              State     ID               Pri  Dead
172.27.0.9       ae0.0                  Full      172.27.255.4     128    39
172.27.0.2       ge-0/0/0.0             Full      172.27.255.2     128    34
172.27.0.13      ge-0/0/1.0             Full      172.27.255.3     128    37

root@R2# run show ospf neighbor
Address          Interface              State     ID               Pri  Dead
172.27.0.1       ge-0/0/0.0             Full      172.27.255.1     128    33
172.27.0.6       ge-0/0/1.0             Full      172.27.255.4     128    39

Thank you all for all your help !!! :-)