Description

We're using MX204 for Broadband PPPoE aggregation, we've seen symptoms as:

- missing accounting packets for some users

- DHCPv6 doesn't return any response (although radius logs showing this is sent correctly)

 

We are seeing these error messages incrementing:

 

Jun 4 03:04:41 bng31 fpc0 PFE_ERROR_INVALID_STATE: Filter index 167800205 already exists (used by flow_id 240988), marking as orphaned

Jun 4 03:04:41 bng31 fpc0 PFE_ERROR_NOT_FOUND: Flow 17361997 => Underlying Flow 525794 not found

Jun 4 03:04:41 bng31 fpc0 PFE_ERROR_FAIL_OPERATION: Flow 17361997 => Failed to create flow with error=15

Jun 4 03:04:41 bng31 fpc0 PFE_ERROR_NOT_FOUND: Flow 17361998 => Underlying Flow 525794 not found

Jun 4 03:04:41 bng31 fpc0 PFE_ERROR_FAIL_OPERATION: Flow 17361998 => Failed to create flow with error=15

 

* Is this a known bug? if yes, we want to know what severity it is and what other things are broken so we can understand how to respond in this situation.

* is there known fix for this ?

* other ways to recover besides rebooting?

 

We've seen it multiple times now, the first occurence was cleared by rebooting the MX204 (hostname mlganxd-bng22 Junos 22.4)

 

Currently we found 3 more boxes are producing the same symptoms:

bng31 - most frequent - junos 22.4 - missing accounting packets

bng32 - less frequent - junos 20.4 - reported case where DHCP PD doesnt work.

bng33 - less frequent - junos 22.4

 

Currently just minor business impact from broken Accounting records for some users and Dual-stack IPv6 (most likely failover to IPv4 and not widely reported)

Symptoms

- missing accounting packets for some users

- DHCPv6 doesn't return any response (although radius logs showing this is sent correctly)

- frequent occurrence of syslog "PFE_ERROR_INVALID_STATE: Filter index 167800205 already exists (used by flow_id 240988), marking as orphaned"

Solution

Troubleshooting with customer found there has frequent authd and jdhcpd restarting, but no daemon core dump file.

May 23 05:50:05 bng31 jlaunchd: general-authentication-service (PID 51413) terminated by signal number 9!

May 23 05:50:05 bng31 jlaunchd: Registered PID 82742(general-authentication-service): exec_command

May 23 05:50:05 bng31 jlaunchd: general-authentication-service (PID 82742) started

May 23 05:50:05 bng31 jlaunchd: Registered PID 82742(general-authentication-service): new process

May 23 05:50:07 bng31 jlaunchd: dhcp-service (PID 51418) exited with status=0 Normal Exit

May 23 05:50:07 bng31 jlaunchd: Registered PID 82760(dhcp-service): exec_command

May 23 05:50:07 bng31 jlaunchd: dhcp-service (PID 82760) started

 

That should be the reason for the accouinng issue and the orphaned filter error.

Further investigation found there has lots of sts_lock_holder core dump files in the /var/tmp direcotry.

-rw-rw-rw- 1 root wheel 496521216 May 23 14:45 sts_lock_holder.pid82742.lock

-rw-rw-rw- 1 root wheel 337907712 May 23 14:45 sts_lock_holder.pid82760.lock

Noted, in higher JUNOS release, such core dump file had been changed to include the pid number and the keyword "lock"instead of using "core" or "dump".

 

Debugging of those core dump files shows that it is because of the authd and the jdhcpd both are asking for the same SDB STS locks thus causes a dead lock. In some old PRs, such as PR1616019 said

SDB STS lock deadlock detection detected lock deadlock and broke the deadlock.

Due to complexity of multiple processes potentially wanting to concurrently take multiple SDB STS locks where lock order

is unknown based on client and service session ids SDB STS deadlock can rarely occur.

The deadlock detection logic breaks deadlock and after processes are restarted system functions normally.

 

But in this case, the dead lock happened very frequently across many BNG routers. It might mainly because of DHCPv6 over PPPoE is enabled and the end clients CPEs are sending large number of DHCPv6 Solicit requests.
jddosd[33958]: DDOS_PROTOCOL_VIOLATION_SET: Warning: Host-bound traffic for protocol/exception  DHCPv6:solicit exceeded its allowed bandwidth at fpc 0 for 1 times

Hence JTAC filed PR1818781 and the fix is by both giving the client lock and trying again to get both locks with each using a random timeout, thus one process should get chance to get both locks and avoid the deadlock.

 

PR1818781 had been fixed in junos:23.2R2-S2, junos:24.2R2, junos:24.3R1 and onwards.


On the other hand, JTAC has recommended customer to enable DDoS protection for DHCPv6 Solicit. After that, the occurrence of the processes crash reduced.

Also this is the graph showing our process restarts had reduced after ddos protection were configured on 3/7. There are less process crashes now.

 

 

 

 

 

Modification History

2024-08-02 : Article Created