Hi ,
I have connected two boxes back to back and have started ptp daemon.After BMC identifies the master and slave , the slave node keeps goign into faulty state and resets back to slave again.
Here's the output from slave node:It complains about another foreign master even though i have just 2 nodes and one interface connected back to back
(ptpd debug1) (lstn_init) activity
(ptpd debug2) (lstn_init) TimerUpdate: Timer 3 has now expired. (Re-armed again with interval 192, left 192)
(ptpd debug2) (lstn_init) timerExpired: Timer 3 expired, taking actions. current interval: 192; current left: 192
(ptpd debug1) (lstn_init) event ANNOUNCE_RECEIPT_TIMEOUT_EXPIRES
(ptpd debug2) (lstn_init) timerStop: Stopping timer 3. (New interval: 192; New left: 0)
(ptpd debug2) (lstn_init) timerStop: Stopping timer 2. (New interval: 0; New left: 0)
(ptpd debug2) (lstn_init) timerStop: Stopping timer 4. (New interval: 0; New left: 0)
(ptpd debug2) (lstn_init) timerStop: Stopping timer 0. (New interval: 0; New left: 0)
(ptpd debug2) (lstn_init) timerStop: Stopping timer 1. (New interval: 0; New left: 0)
(ptpd debug1) (lstn_init) netRefreshIGMP
(ptpd info) (lstn_init) refreshed IGMP multicast memberships
(ptpd debug1) (lstn_init) state PTP_LISTENING
(ptpd info) (lstn_init) now in state PTP_LISTENING
(ptpd debug2) (lstn_init) timerStart: Set timer 3 to 12.000000. New interval: 192; new left: 192
(ptpd debug1) (lstn_init) activity
(ptpd debug1) (lstn_init) handle: something
First question - which ptpd2 version are you using? Second - the faulty state is temporary in ptpd and is instantly progressed to initializing - in the log below, faulty appears during a clock jump - or in fact while switching to the fastest slewing mode. I also see "board_time" which is telling me that this is modified code using hardware support - we can't tell what exactly is happening. Previously ptpd would also switch to faulty state when it received malformed or too short messages - but in the latest code it ignores those conditions and increments error counters instead, and anyway in the log there are no signs of this happening.
Regards,
Wojciech
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Hi ,
I have connected two boxes back to back and have started ptp daemon.After BMC identifies the master and slave , the slave node keeps goign into faulty state and resets back to slave again.
Here's the output from slave node:It complains about another foreign master even though i have just 2 nodes and one interface connected back to back
(ptpd debug1) (lstn_init) activity
(ptpd debug2) (lstn_init) TimerUpdate: Timer 3 has now expired. (Re-armed again with interval 192, left 192)
(ptpd debug2) (lstn_init) timerExpired: Timer 3 expired, taking actions. current interval: 192; current left: 192
(ptpd debug1) (lstn_init) event ANNOUNCE_RECEIPT_TIMEOUT_EXPIRES
(ptpd debug2) (lstn_init) timerStop: Stopping timer 3. (New interval: 192; New left: 0)
(ptpd debug2) (lstn_init) timerStop: Stopping timer 2. (New interval: 0; New left: 0)
(ptpd debug2) (lstn_init) timerStop: Stopping timer 4. (New interval: 0; New left: 0)
(ptpd debug2) (lstn_init) timerStop: Stopping timer 0. (New interval: 0; New left: 0)
(ptpd debug2) (lstn_init) timerStop: Stopping timer 1. (New interval: 0; New left: 0)
(ptpd debug1) (lstn_init) netRefreshIGMP
(ptpd info) (lstn_init) refreshed IGMP multicast memberships
(ptpd debug1) (lstn_init) state PTP_LISTENING
(ptpd info) (lstn_init) now in state PTP_LISTENING
(ptpd debug2) (lstn_init) timerStart: Set timer 3 to 12.000000. New interval: 192; new left: 192
(ptpd debug1) (lstn_init) activity
(ptpd debug1) (lstn_init) handle: something
Ret from event is 44
(ptpd debug1) (lstn_init) kernel NANO recv time stamp 1375747765s 713584154ns
(ptpd debug1) (lstn_init) __UTC_offset: 0 0
(ptpd debug1) (lstn_init) Message header :
(ptpd debug1) (lstn_init)
(ptpd debug1) (lstn_init) transportSpecific : 8
(ptpd debug1) (lstn_init) messageType : 0
(ptpd debug1) (lstn_init) versionPTP : 2
(ptpd debug1) (lstn_init) messageLength : 44
(ptpd debug1) (lstn_init) domainNumber : 0
(ptpd debug1) (lstn_init) FlagField 02:00
(ptpd debug1) (lstn_init) Integer 64 :
(ptpd debug1) (lstn_init) LSB : 0
(ptpd debug1) (lstn_init) MSB : 0
(ptpd debug1) (lstn_init) ClockIdentity : 00:25:90:ff:fe:14:bd:f6
(ptpd debug1) (lstn_init) port number : 1
(ptpd debug1) (lstn_init) sequenceId : 0
(ptpd debug1) (lstn_init) controlField : 0
(ptpd debug1) (lstn_init) logMessageInterval : 0
(ptpd debug1) (lstn_init)
(ptpd debug1) (lstn_init) ==> Sync received
(ptpd debug1) (lstn_init) Sync message received :
(ptpd debug1) (lstn_init) HandleSync: Sync message received from another Master
(ptpd debug1) (lstn_init) activity
(ptpd debug1) (lstn_init) handle: something
Ret from event is -1
(ptpd debug1) (lstn_init) netRecvGeneral: ret
Ret is 44
(ptpd debug1) (lstn_init) netRecvGeneral: SCM_BINTIME
(ptpd debug1) (lstn_init) kernel NANO recv time stamp 1375747765s 614944487ns
(ptpd debug1) (lstn_init) netRecvGeneral: end
return from netrecvGenral in handle 44
(ptpd debug1) (lstn_init) __UTC_offset: 0 0
(ptpd debug1) (lstn_init) Message header :
(ptpd debug1) (lstn_init)
(ptpd debug1) (lstn_init) transportSpecific : 8
(ptpd debug1) (lstn_init) messageType : 8
(ptpd debug1) (lstn_init) versionPTP : 2
(ptpd debug1) (lstn_init) messageLength : 44
(ptpd debug1) (lstn_init) domainNumber : 0
(ptpd debug1) (lstn_init) FlagField 02:00
(ptpd debug1) (lstn_init) Integer 64 :
(ptpd debug1) (lstn_init) LSB : 0
(ptpd debug1) (lstn_init) MSB : 0
(ptpd debug1) (lstn_init) ClockIdentity : 00:25:90:ff:fe:14:bd:f6
(ptpd debug1) (lstn_init) port number : 1
(ptpd debug1) (lstn_init) sequenceId : 0
(ptpd debug1) (lstn_init) controlField : 2
(ptpd debug1) (lstn_init) logMessageInterval : 0
(ptpd debug1) (lstn_init)
(ptpd debug1) (lstn_init) ==> FollowUp received
(ptpd debug1) (lstn_init) Handlefollowup : Follow up message received
(ptpd debug1) (lstn_init) Handfollowup : disregard
(ptpd debug1) (lstn_init) activity
(ptpd debug1) (lstn_init) handle: something
Ret from event is 44
(ptpd debug1) (lstn_init) kernel NANO recv time stamp 1375747766s 631097108ns
(ptpd debug1) (lstn_init) __UTC_offset: 0 0
(ptpd debug1) (lstn_init) Message header :
(ptpd debug1) (lstn_init)
(ptpd debug1) (lstn_init) transportSpecific : 8
(ptpd debug1) (lstn_init) messageType : 0
(ptpd debug1) (lstn_init) versionPTP : 2
(ptpd debug1) (lstn_init) messageLength : 44
(ptpd debug1) (lstn_init) domainNumber : 0
(ptpd debug1) (lstn_init) FlagField 02:00
(ptpd debug1) (lstn_init) Integer 64 :
(ptpd debug1) (lstn_init) LSB : 0
(ptpd debug1) (lstn_init) MSB : 0
(ptpd debug1) (lstn_init) ClockIdentity : 00:25:90:ff:fe:14:bd:f6
(ptpd debug1) (lstn_init) port number : 1
(ptpd debug1) (lstn_init) sequenceId : 1
(ptpd debug1) (lstn_init) controlField : 0
(ptpd debug1) (lstn_init) logMessageInterval : 0
(ptpd debug1) (lstn_init)
(ptpd debug1) (lstn_init) ==> Sync received
(ptpd debug1) (lstn_init) Sync message received :
(ptpd debug1) (lstn_init) HandleSync: Sync message received from another Master
(ptpd debug1) (lstn_init) activity
(ptpd debug1) (lstn_init) handle: something
Ret from event is -1
(ptpd debug1) (lstn_init) netRecvGeneral: ret
Ret is 64
(ptpd debug1) (lstn_init) netRecvGeneral: SCM_BINTIME
(ptpd debug1) (lstn_init) kernel NANO recv time stamp 1375747766s 591575324ns
(ptpd debug1) (lstn_init) netRecvGeneral: end
return from netrecvGenral in handle 64
(ptpd debug1) (lstn_init) __UTC_offset: 0 0
(ptpd debug1) (lstn_init) Message header :
(ptpd debug1) (lstn_init)
(ptpd debug1) (lstn_init) transportSpecific : 8
(ptpd debug1) (lstn_init) messageType : 11
(ptpd debug1) (lstn_init) versionPTP : 2
(ptpd debug1) (lstn_init) messageLength : 64
(ptpd debug1) (lstn_init) domainNumber : 0
(ptpd debug1) (lstn_init) FlagField 02:00
(ptpd debug1) (lstn_init) Integer 64 :
(ptpd debug1) (lstn_init) LSB : 0
(ptpd debug1) (lstn_init) MSB : 0
(ptpd debug1) (lstn_init) ClockIdentity : 00:25:90:ff:fe:14:bd:f6
(ptpd debug1) (lstn_init) port number : 1
(ptpd debug1) (lstn_init) sequenceId : 0
(ptpd debug1) (lstn_init) controlField : 5
(ptpd debug1) (lstn_init) logMessageInterval : 1
(ptpd debug1) (lstn_init)
(ptpd debug1) (lstn_init)
slv, 0.000000000, 0.000000000, 0 ==> Announce received
(ptpd debug1) (lstn_init) HandleAnnounce : Announce message received :
(ptpd debug1) (lstn_init) Announce message from another foreign master
(ptpd debug1) (lstn_init) Message header :
(ptpd debug1) (lstn_init)
(ptpd debug1) (lstn_init) transportSpecific : 8
(ptpd debug1) (lstn_init) messageType : 11
(ptpd debug1) (lstn_init) versionPTP : 2
(ptpd debug1) (lstn_init) messageLength : 64
(ptpd debug1) (lstn_init) domainNumber : 0
(ptpd debug1) (lstn_init) FlagField 02:00
(ptpd debug1) (lstn_init) Integer 64 :
(ptpd debug1) (lstn_init) LSB : 0
(ptpd debug1) (lstn_init) MSB : 0
(ptpd debug1) (lstn_init) ClockIdentity : 00:25:90:ff:fe:14:bd:f6
(ptpd debug1) (lstn_init) port number : 1
(ptpd debug1) (lstn_init) sequenceId : 0
(ptpd debug1) (lstn_init) controlField : 5
(ptpd debug1) (lstn_init) logMessageInterval : 1
(ptpd debug1) (lstn_init)
(ptpd debug1) (lstn_init) Announce Message :
(ptpd debug1) (lstn_init)
(ptpd debug1) (lstn_init) originTimestamp :
(ptpd debug1) (lstn_init) secondField :
(ptpd debug1) (lstn_init) Integer 48 :
(ptpd debug1) (lstn_init) LSB : 0
(ptpd debug1) (lstn_init) MSB : 0
(ptpd debug1) (lstn_init) nanoseconds 0
(ptpd debug1) (lstn_init) currentUtcOffset : 0
(ptpd debug1) (lstn_init) grandMasterPriority1 : 128
(ptpd debug1) (lstn_init) grandMasterClockQuality :
(ptpd debug1) (lstn_init) clockClass : 248
(ptpd debug1) (lstn_init) clockAccuracy : 254
(ptpd debug1) (lstn_init) offsetScaledLogVariance : 28768
(ptpd debug1) (lstn_init) grandMasterPriority2 : 128
(ptpd debug1) (lstn_init) grandMasterIdentity :
(ptpd debug1) (lstn_init) ClockIdentity : 00:25:90:ff:fe:14:bd:f6
(ptpd debug1) (lstn_init) stepsRemoved : 0
(ptpd debug1) (lstn_init) timeSource : 160
(ptpd debug1) (lstn_init)
(ptpd debug1) (lstn_init) New foreign Master added
(ptpd debug1) (lstn_init) activity
(ptpd info) (lstn_init)
Entering BMC
(ptpd debug2) (lstn_init) event STATE_DECISION_EVENT
(ptpd debug1) (lstn_init) number_foreign_records : 1
(ptpd debug1) (lstn_init) Best record : 0
(ptpd debug2) (lstn_init) timerStop: Stopping timer 3. (New interval: 140; New left: 0)
(ptpd notice) (lstn_init) state PTP_SLAVE
(ptpd info) (lstn_init) now in state PTP_SLAVE
(ptpd debug1) (lstn_init) initClock
(ptpd debug2) (lstn_init) adj is 0; t freq is 0 (float: 0.000000 Integer32: 0)
(ptpd debug2) (lstn_init) timerStart: Set timer 6 to 300.000000. New interval: 4800; new left: 4800
(ptpd debug2) (lstn_init) timerStart: Set timer 3 to 12.000000. New interval: 192; new left: 192
(ptpd debug1) (slv) handle: something
Ret from event is -1
(ptpd debug1) (slv) netRecvGeneral: ret
Ret is 44
(ptpd debug1) (slv) netRecvGeneral: SCM_BINTIME
(ptpd debug1) (slv) kernel NANO recv time stamp 1375747766s 655739039ns
(ptpd debug1) (slv) netRecvGeneral: end
return from netrecvGenral in handle 44
(ptpd debug1) (slv) __UTC_offset: 0 0
(ptpd debug1) (slv) Message header :
(ptpd debug1) (slv)
(ptpd debug1) (slv) transportSpecific : 8
(ptpd debug1) (slv) messageType : 8
(ptpd debug1) (slv) versionPTP : 2
(ptpd debug1) (slv) messageLength : 44
(ptpd debug1) (slv) domainNumber : 0
(ptpd debug1) (slv) FlagField 02:00
(ptpd debug1) (slv) Integer 64 :
(ptpd debug1) (slv) LSB : 0
(ptpd debug1) (slv) MSB : 0
(ptpd debug1) (slv) ClockIdentity : 00:25:90:ff:fe:14:bd:f6
(ptpd debug1) (slv) port number : 1
(ptpd debug1) (slv) sequenceId : 1
(ptpd debug1) (slv) controlField : 2
(ptpd debug1) (slv) logMessageInterval : 0
(ptpd debug1) (slv)
(ptpd debug1) (slv) ==> FollowUp received
(ptpd debug1) (slv) Handlefollowup : Follow up message received
(ptpd debug2) (slv) Ignored followup, Slave was not waiting a follow up message
(ptpd debug1) (slv) Ignored, Follow up message received from another master
(ptpd debug1) (slv) activity
(ptpd debug1) (slv) handle: something
Ret from event is 44
(ptpd debug1) (slv) kernel NANO recv time stamp 1375747767s 664250969ns
(ptpd debug1) (slv) __UTC_offset: 0 0
(ptpd debug1) (slv) Message header :
(ptpd debug1) (slv)
(ptpd debug1) (slv) transportSpecific : 8
(ptpd debug1) (slv) messageType : 0
(ptpd debug1) (slv) versionPTP : 2
(ptpd debug1) (slv) messageLength : 44
(ptpd debug1) (slv) domainNumber : 0
(ptpd debug1) (slv) FlagField 02:00
(ptpd debug1) (slv) Integer 64 :
(ptpd debug1) (slv) LSB : 0
(ptpd debug1) (slv) MSB : 0
(ptpd debug1) (slv) ClockIdentity : 00:25:90:ff:fe:14:bd:f6
(ptpd debug1) (slv) port number : 1
(ptpd debug1) (slv) sequenceId : 2
(ptpd debug1) (slv) controlField : 0
(ptpd debug1) (slv) logMessageInterval : 0
(ptpd debug1) (slv)
(ptpd debug1) (slv) ==> Sync received
(ptpd debug1) (slv) Sync message received :
(ptpd notice) (slv) Received first Sync from Master
(ptpd notice) (slv) going to arm DelayReq timer for the first time, with initial rate: 0
(ptpd debug2) (slv) timerStart: Set timer 1 to 1.000000. New interval: 16; new left: 16
(ptpd debug2) (slv) HandleSync: waiting for follow-up
(ptpd debug1) (slv) activity
(ptpd debug1) (slv) handle: something
Ret from event is -1
(ptpd debug1) (slv) netRecvGeneral: ret
Ret is 44
(ptpd debug1) (slv) netRecvGeneral: SCM_BINTIME
(ptpd debug1) (slv) kernel NANO recv time stamp 1375747767s 820144772ns
(ptpd debug1) (slv) netRecvGeneral: end
return from netrecvGenral in handle 44
(ptpd debug1) (slv) __UTC_offset: 0 0
(ptpd debug1) (slv) Message header :
(ptpd debug1) (slv)
(ptpd debug1) (slv) transportSpecific : 8
(ptpd debug1) (slv) messageType : 8
(ptpd debug1) (slv) versionPTP : 2
(ptpd debug1) (slv) messageLength : 44
(ptpd debug1) (slv) domainNumber : 0
(ptpd debug1) (slv) FlagField 02:00
(ptpd debug1) (slv) Integer 64 :
(ptpd debug1) (slv) LSB : 0
(ptpd debug1) (slv) MSB : 0
(ptpd debug1) (slv) ClockIdentity : 00:25:90:ff:fe:14:bd:f6
(ptpd debug1) (slv) port number : 1
(ptpd debug1) (slv) sequenceId : 2
(ptpd debug1) (slv) controlField : 2
(ptpd debug1) (slv) logMessageInterval : 0
(ptpd debug1) (slv)
(ptpd debug1) (slv) ==> FollowUp received
(ptpd debug1) (slv) Handlefollowup : Follow up message received
(ptpd debug1) (slv) Integer 48 :
(ptpd debug1) (slv) LSB : 0
(ptpd debug1) (slv) MSB : 0
(ptpd debug1) (slv) nanoseconds 0
(ptpd debug1) (slv) ==> updateOffset
(ptpd debug1) (slv) ==> updateClock
(ptpd warning) (slv) Performing hard frequency reset, by setting frequency to zero
(ptpd debug2) (slv) adj is 0; t freq is 0 (float: 0.000000 Integer32: 0)
(ptpd notice) (slv) resetting system clock to 0s 0ns
(ptpd debug1) (slv) initClock
(ptpd debug2) (slv) adj is 0; t freq is 0 (float: 0.000000 Integer32: 0)
(ptpd debug2) (slv)
flt
flt
init
lstn timerStop: Stopping timer 3. (New interval: 176; New left: 0)
(ptpd debug2) (slv) timerStop: Stopping timer 1. (New interval: 16; New left: 0)
(ptpd debug1) (slv) initClock
(ptpd debug2) (slv) adj is 0; t freq is 0 (float: 0.000000 Integer32: 0)
(ptpd notice) (slv) state PTP_FAULTY
(ptpd debug1) (flt)
--Offset Correction--
(ptpd debug1) (flt) Raw offset from master: 0s 0ns
(ptpd debug1) (flt)
--Offset and Delay filtered--
(ptpd debug1) (flt) one-way delay averaged (E2E): 0s 0ns
(ptpd notice) (flt) offset from master: 0s 0ns
(ptpd debug1) (flt) observed drift: 0
(ptpd debug1) (flt) activity
(ptpd debug1) (flt) event FAULT_CLEARED
(ptpd notice) (flt) state PTP_INITIALIZING
(ptpd debug1) (init) activity
(ptpd debug1) (init) manufacturerIdentity: PTPD;2.0.0
Last edit: varks123 2013-08-06
Hi,
First question - which ptpd2 version are you using? Second - the faulty state is temporary in ptpd and is instantly progressed to initializing - in the log below, faulty appears during a clock jump - or in fact while switching to the fastest slewing mode. I also see "board_time" which is telling me that this is modified code using hardware support - we can't tell what exactly is happening. Previously ptpd would also switch to faulty state when it received malformed or too short messages - but in the latest code it ignores those conditions and increments error counters instead, and anyway in the log there are no signs of this happening.
Regards,
Wojciech