Skip to content
This repository has been archived by the owner on Oct 1, 2023. It is now read-only.

Getting "Watchdog not fed within ..." and "CanFrame too stale" issues when using Sysid #471

Closed
jasonli0616 opened this issue Jan 21, 2023 · 3 comments
Closed

Getting "Watchdog not fed within ..." and "CanFrame too stale" issues when using Sysid #471

jasonli0616 opened this issue Jan 21, 2023 · 3 comments
Labels
component: generation Generation of robot projects

Comments

@jasonli0616
Copy link

No issues occur at all when running our robot code, however these issues happen when we are using Sysid.

When running any of the Sysid tests, we enable, the robot does not move, and the errors appear upon disabling the robot (see log below).

The robot worked a couple of times (with Sysid), got some results, then just stopped working out of the blue (no changes on our part).

We are on WPILib 2023.2.1, and the 2023 version of NI FRC Game Tools (both latest as of today).

Config:

{
  "counts per rotation": 4096.0,
  "encoder type": "CANCoder",
  "encoding": false,
  "gearing denominator": 1.0,
  "gearing numerator": 1.0,
  "gyro": "Pigeon2",
  "gyro ctor": "10",
  "is drivetrain": true,
  "motor controllers": [
    "TalonFX",
    "TalonFX",
    "TalonFX"
  ],
  "number of samples per average": 1,
  "primary encoder inverted": true,
  "primary encoder ports": [
    30,
    1
  ],
  "primary motor ports": [
    20,
    21,
    22
  ],
  "primary motors inverted": [
    true,
    true,
    true
  ],
  "secondary encoder inverted": false,
  "secondary encoder ports": [
    29,
    2
  ],
  "secondary motor ports": [
    23,
    24,
    25
  ],
  "secondary motors inverted": [
    false,
    false,
    false
  ],
  "velocity measurement period": 100
}

This is the error log:

[
    {
        "messageType": 2,
        "timestamp": -0.000030517578125,
        "seqNumber": 414,
        "line": ""
    },
    {
        "messageType": 2,
        "timestamp": 0.001373291015625,
        "seqNumber": 415,
        "line": "********** Robot program starting **********"
    },
    {
        "messageType": 2,
        "timestamp": 0.0042724609375,
        "seqNumber": 416,
        "line": "Camera Server Library Not Found"
    },
    {
        "messageType": 2,
        "timestamp": 0.008941650390625,
        "seqNumber": 417,
        "line": "NT: could not open persistent file '/home/lvuser/networktables.json': No such file or directory"
    },
    {
        "messageType": 2,
        "timestamp": 0.011138916015625,
        "seqNumber": 418,
        "line": "NT: Listening on NT3 port 1735, NT4 port 5810"
    },
    {
        "messageType": 2,
        "timestamp": 0.018890380859375,
        "seqNumber": 419,
        "line": "Initializing logger"
    },
    {
        "messageType": 2,
        "timestamp": 0.02117919921875,
        "seqNumber": 420,
        "line": "Read JSON"
    },
    {
        "messageType": 2,
        "timestamp": 0.02197265625,
        "seqNumber": 421,
        "line": "NT: Got a NT4 connection from 10.54.9.162 port 62583"
    },
    {
        "messageType": 2,
        "timestamp": 0.023681640625,
        "seqNumber": 422,
        "line": "Setup motors"
    },
    {
        "messageType": 2,
        "timestamp": 0.0245361328125,
        "seqNumber": 423,
        "line": "Setup TalonFX"
    },
    {
        "messageType": 2,
        "timestamp": 0.027069091796875,
        "seqNumber": 424,
        "line": "NT: CONNECTED NT4 client 'shuffleboard' (from 10.54.9.162:62583)"
    },
    {
        "messageType": 2,
        "timestamp": 0.02783203125,
        "seqNumber": 425,
        "line": "Setup TalonFX"
    },
    {
        "messageType": 2,
        "timestamp": 0.031951904296875,
        "seqNumber": 426,
        "line": "Setup TalonFX"
    },
    {
        "messageType": 2,
        "timestamp": 0.03375244140625,
        "seqNumber": 427,
        "line": "Setup TalonFX"
    },
    {
        "messageType": 2,
        "timestamp": 0.036224365234375,
        "seqNumber": 428,
        "line": "Setup TalonFX"
    },
    {
        "messageType": 2,
        "timestamp": 0.040130615234375,
        "seqNumber": 429,
        "line": "Setup TalonFX"
    },
    {
        "messageType": 2,
        "timestamp": 0.043243408203125,
        "seqNumber": 430,
        "line": "Setup encoders"
    },
    {
        "messageType": 2,
        "timestamp": 0.044403076171875,
        "seqNumber": 431,
        "line": "Setup CANCoder"
    },
    {
        "messageType": 2,
        "timestamp": 0.045623779296875,
        "seqNumber": 432,
        "line": "Setup CANCoder"
    },
    {
        "messageType": 2,
        "timestamp": 0.05340576171875,
        "seqNumber": 433,
        "line": "Setup gyro"
    },
    {
        "messageType": 2,
        "timestamp": 0.054351806640625,
        "seqNumber": 434,
        "line": "Setup Pigeon2, 10 (CAN)"
    },
    {
        "messageType": 2,
        "timestamp": 0.055419921875,
        "seqNumber": 435,
        "line": "Setting default"
    },
    {
        "messageType": 2,
        "timestamp": 0.05572509765625,
        "seqNumber": 436,
        "line": ""
    },
    {
        "messageType": 2,
        "timestamp": 0.0560302734375,
        "seqNumber": 437,
        "line": "********** Robot program startup complete **********"
    },
    {
        "messageType": 2,
        "timestamp": 0.056396484375,
        "seqNumber": 438,
        "line": "Robot disabled"
    },
    {
        "messageType": 2,
        "timestamp": 0.05694580078125,
        "seqNumber": 439,
        "line": "Collected: 0 data points."
    },
    {
        "messageType": 2,
        "timestamp": 0.06390380859375,
        "seqNumber": 440,
        "line": "NT: Got a NT4 connection from 10.54.9.237 port 54141"
    },
    {
        "messageType": 2,
        "timestamp": 0.066864013671875,
        "seqNumber": 441,
        "line": "NT: Got a NT4 connection from 10.54.9.237 port 54143"
    },
    {
        "messageType": 2,
        "timestamp": 0.067474365234375,
        "seqNumber": 442,
        "line": "NT: CONNECTED NT4 client 'sysid' (from 10.54.9.237:54141)"
    },
    {
        "messageType": 2,
        "timestamp": 0.0687255859375,
        "seqNumber": 443,
        "line": "NT: CONNECTED NT4 client 'sysid@1' (from 10.54.9.237:54143)"
    },
    {
        "messageType": 2,
        "timestamp": 0.07025146484375,
        "seqNumber": 444,
        "line": "NT: DISCONNECTED NT4 client 'sysid@1' (from 10.54.9.237:54143): remote end closed connection"
    },
    {
        "messageType": 2,
        "timestamp": 0.071197509765625,
        "seqNumber": 445,
        "line": "NT: NT4 socket error: operation canceled"
    },
    {
        "timestamp": 3.02667236328125,
        "seqNumber": 446,
        "numOccur": 1,
        "errorCode": 0,
        "flags": 0,
        "details": "[phoenix] Library initialization is complete.",
        "location": "",
        "callStack": "",
        "messageType": 1
    },
    {
        "timestamp": 4.652313232421875,
        "seqNumber": 447,
        "numOccur": 1,
        "errorCode": 0,
        "flags": 0,
        "details": "[phoenix-diagnostics] Server 2023.0.0 (Dec 21 2022, 20:14:40) running on port: 1250",
        "location": "",
        "callStack": "",
        "messageType": 1
    },
    {
        "messageType": 2,
        "timestamp": 23.1953125,
        "seqNumber": 448,
        "line": "Robot disabled"
    },
    {
        "messageType": 2,
        "timestamp": 23.19879150390625,
        "seqNumber": 449,
        "line": "Collected: 14931 data points."
    },
    {
        "timestamp": 23.20550537109375,
        "seqNumber": 450,
        "numOccur": 1,
        "errorCode": 16,
        "flags": 0,
        "details": "Warning: Watchdog not fed within 0.005000s",
        "location": "Main",
        "callStack": "\tat frc::ReportErrorV(int, char const*, int, char const*, fmt::v9::basic_string_view<char>, fmt::v9::basic_format_args<fmt::v9::basic_format_context<fmt::v9::appender, char> >) + 0x178 [0xb6b5737c]\n\tat frc::Watchdog::Impl::Main() + 0x274 [0xb6b211f4]\n\tat  + 0xae2b8 [0xb61c22b8]\n",
        "messageType": 1
    },
    {
        "messageType": 2,
        "timestamp": 23.20672607421875,
        "seqNumber": 451,
        "line": "Warning at Main: Warning: Watchdog not fed within 0.005000s"
    },
    {
        "messageType": 2,
        "timestamp": 23.207122802734375,
        "seqNumber": 452,
        "line": "\tat frc::ReportErrorV(int, char const*, int, char const*, fmt::v9::basic_string_view<char>, fmt::v9::basic_format_args<fmt::v9::basic_format_context<fmt::v9::appender, char> >) + 0x178 [0xb6b5737c]"
    },
    {
        "messageType": 2,
        "timestamp": 23.208282470703125,
        "seqNumber": 453,
        "line": "\tat frc::Watchdog::Impl::Main() + 0x274 [0xb6b211f4]"
    },
    {
        "messageType": 2,
        "timestamp": 23.20855712890625,
        "seqNumber": 454,
        "line": "\tat  + 0xae2b8 [0xb61c22b8]"
    },
    {
        "messageType": 2,
        "timestamp": 23.20892333984375,
        "seqNumber": 455,
        "line": ""
    },
    {
        "timestamp": 23.213592529296875,
        "seqNumber": 456,
        "numOccur": 1,
        "errorCode": -111,
        "flags": 1,
        "details": "Error: Loop time of 0.005000s overrun",
        "location": "PrintLoopOverrunMessage",
        "callStack": "\tat frc::ReportErrorV(int, char const*, int, char const*, fmt::v9::basic_string_view<char>, fmt::v9::basic_format_args<fmt::v9::basic_format_context<fmt::v9::appender, char> >) + 0x178 [0xb6b5737c]\n\tat frc::IterativeRobotBase::PrintLoopOverrunMessage() + 0x70 [0xb6af0240]\n\tat frc::Watchdog::Impl::Main() + 0x94 [0xb6b21014]\n\tat  + 0xae2b8 [0xb61c22b8]\n",
        "messageType": 0
    },
    {
        "messageType": 2,
        "timestamp": 23.21453857421875,
        "seqNumber": 457,
        "line": "Error at PrintLoopOverrunMessage: Error: Loop time of 0.005000s overrun"
    },
    {
        "messageType": 2,
        "timestamp": 23.214935302734375,
        "seqNumber": 458,
        "line": "\tat frc::ReportErrorV(int, char const*, int, char const*, fmt::v9::basic_string_view<char>, fmt::v9::basic_format_args<fmt::v9::basic_format_context<fmt::v9::appender, char> >) + 0x178 [0xb6b5737c]"
    },
    {
        "messageType": 2,
        "timestamp": 23.21588134765625,
        "seqNumber": 459,
        "line": "\tat frc::IterativeRobotBase::PrintLoopOverrunMessage() + 0x70 [0xb6af0240]"
    },
    {
        "messageType": 2,
        "timestamp": 23.216156005859375,
        "seqNumber": 460,
        "line": "\tat frc::Watchdog::Impl::Main() + 0x94 [0xb6b21014]"
    },
    {
        "messageType": 2,
        "timestamp": 23.216400146484375,
        "seqNumber": 461,
        "line": "\tat  + 0xae2b8 [0xb61c22b8]"
    },
    {
        "messageType": 2,
        "timestamp": 23.216644287109375,
        "seqNumber": 462,
        "line": ""
    },
    {
        "timestamp": 23.24078369140625,
        "seqNumber": 463,
        "numOccur": 1,
        "errorCode": 16,
        "flags": 0,
        "details": "Warning: \tLiveWindow::UpdateValues(): 0.000007s\n\tRobotPeriodic(): 0.000009s\n\tSmartDashboard::UpdateValues(): 0.000009s\n\tDisabledPeriodic(): 0.000711s\n\tDisabledInit(): 0.048147s\n\tShuffleboard::Update(): 0.000007s\n",
        "location": "PrintEpochs",
        "callStack": "\tat frc::ReportErrorV(int, char const*, int, char const*, fmt::v9::basic_string_view<char>, fmt::v9::basic_format_args<fmt::v9::basic_format_context<fmt::v9::appender, char> >) + 0x178 [0xb6b5737c]\n\tat frc::Tracer::PrintEpochs() + 0x130 [0xb6b740bc]\n\tat frc::IterativeRobotBase::LoopFunc() + 0x1ec [0xb6aefc94]\n\tat frc::TimedRobot::StartCompetition() + 0x154 [0xb6ac5de4]\n\tat void frc::impl::RunRobot<DriveRobot>(wpi::priority_mutex&, DriveRobot**) + 0x54 [0x2abf0]\n\tat int frc::StartRobot<DriveRobot>() + 0x1b0 [0x2af00]\n\tat __libc_start_main + 0x10c [0xb5f1c624]\n",
        "messageType": 1
    },
    {
        "messageType": 2,
        "timestamp": 23.242401123046875,
        "seqNumber": 464,
        "line": "Warning at PrintEpochs: Warning: \tLiveWindow::UpdateValues(): 0.000007s"
    },
    {
        "messageType": 2,
        "timestamp": 23.24273681640625,
        "seqNumber": 465,
        "line": "\tRobotPeriodic(): 0.000009s"
    },
    {
        "messageType": 2,
        "timestamp": 23.243011474609375,
        "seqNumber": 466,
        "line": "\tSmartDashboard::UpdateValues(): 0.000009s"
    },
    {
        "messageType": 2,
        "timestamp": 23.243621826171875,
        "seqNumber": 467,
        "line": "\tDisabledPeriodic(): 0.000711s"
    },
    {
        "messageType": 2,
        "timestamp": 23.243927001953125,
        "seqNumber": 468,
        "line": "\tDisabledInit(): 0.048147s"
    },
    {
        "messageType": 2,
        "timestamp": 23.2447509765625,
        "seqNumber": 469,
        "line": "\tShuffleboard::Update(): 0.000007s"
    },
    {
        "messageType": 2,
        "timestamp": 23.245025634765625,
        "seqNumber": 470,
        "line": ""
    },
    {
        "messageType": 2,
        "timestamp": 23.245391845703125,
        "seqNumber": 471,
        "line": "\tat frc::ReportErrorV(int, char const*, int, char const*, fmt::v9::basic_string_view<char>, fmt::v9::basic_format_args<fmt::v9::basic_format_context<fmt::v9::appender, char> >) + 0x178 [0xb6b5737c]"
    },
    {
        "messageType": 2,
        "timestamp": 23.24835205078125,
        "seqNumber": 472,
        "line": "\tat frc::Tracer::PrintEpochs() + 0x130 [0xb6b740bc]"
    },
    {
        "messageType": 2,
        "timestamp": 23.249420166015625,
        "seqNumber": 473,
        "line": "\tat frc::IterativeRobotBase::LoopFunc() + 0x1ec [0xb6aefc94]"
    },
    {
        "messageType": 2,
        "timestamp": 23.249755859375,
        "seqNumber": 474,
        "line": "\tat frc::TimedRobot::StartCompetition() + 0x154 [0xb6ac5de4]"
    },
    {
        "messageType": 2,
        "timestamp": 23.250244140625,
        "seqNumber": 475,
        "line": "\tat void frc::impl::RunRobot<DriveRobot>(wpi::priority_mutex&, DriveRobot**) + 0x54 [0x2abf0]"
    },
    {
        "messageType": 2,
        "timestamp": 23.250762939453125,
        "seqNumber": 476,
        "line": "\tat int frc::StartRobot<DriveRobot>() + 0x1b0 [0x2af00]"
    },
    {
        "messageType": 2,
        "timestamp": 23.251068115234375,
        "seqNumber": 477,
        "line": "\tat __libc_start_main + 0x10c [0xb5f1c624]"
    },
    {
        "messageType": 2,
        "timestamp": 23.25146484375,
        "seqNumber": 478,
        "line": ""
    },
    {
        "timestamp": 23.25640869140625,
        "seqNumber": 479,
        "numOccur": 1,
        "errorCode": -3,
        "flags": 1,
        "details": "CTR: CAN frame not received/too-stale.",
        "location": "Talon FX 20 GetBusVoltage",
        "callStack": "\tat ctre::phoenix::motorcontrol::can::BaseMotorController::GetMotorOutputVoltage()\n\tat sysid::SysIdLogger::MeasureVoltage(std::vector<std::unique_ptr<frc::MotorController, std::default_delete<frc::MotorController> >, std::allocator<std::unique_ptr<frc::MotorController, std::default_delete<frc::MotorController> > > > const&, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > const&)\n\tat DriveRobot::PushNTDiagnostics()\n\tat frc::IterativeRobotBase::LoopFunc()\n\tat frc::TimedRobot::StartCompetition()\n\tat void frc::impl::RunRobot<DriveRobot>(wpi::priority_mutex&, DriveRobot**)\n\tat int frc::StartRobot<DriveRobot>()\n\tat __libc_start_main\n",
        "messageType": 0
    },
    {
        "timestamp": 23.27947998046875,
        "seqNumber": 480,
        "numOccur": 1,
        "errorCode": -3,
        "flags": 1,
        "details": "CTR: CAN frame not received/too-stale.",
        "location": "CANCoder 30 GetPosition",
        "callStack": "Stack Trace not received for performance reasons.",
        "messageType": 0
    },
    {
        "timestamp": 23.280181884765625,
        "seqNumber": 481,
        "numOccur": 1,
        "errorCode": -3,
        "flags": 1,
        "details": "CTR: CAN frame not received/too-stale.",
        "location": "CANCoder 29 GetPosition",
        "callStack": "Stack Trace not received for performance reasons.",
        "messageType": 0
    }
]
@RandomPerson495721
Copy link

I think we had a similar issue, I don't know what the actual cause is, but it seems to be related with network tables. We were able to work around it by going to the logger, resetting the telemetry, changing the mode from Client (NT4) to disabled, apply, then change it back to NT4 and applying again.

@jasonli0616
Copy link
Author

@RandomPerson495721 Thanks for the workaround; we were also able to get it working creating a custom logger (as found on a Chief Delphi post: https://www.chiefdelphi.com/t/sysid-broken-on-2022-2-1/401875). Seems like some other teams on the FRC unofficial discord server were also facing the same issue.

@calcmogul calcmogul added the component: generation Generation of robot projects label Sep 20, 2023
@calcmogul
Copy link
Member

OBE by #518.

@calcmogul calcmogul closed this as not planned Won't fix, can't repro, duplicate, stale Sep 21, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
component: generation Generation of robot projects
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@calcmogul @RandomPerson495721 @jasonli0616