Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Cross RS4S repeated status #499

Open
emiltin opened this issue Jan 16, 2025 · 4 comments
Open

Cross RS4S repeated status #499

emiltin opened this issue Jan 16, 2025 · 4 comments
Labels
equipment Bug in equipment RS4S Cross RS4S

Comments

@emiltin
Copy link
Contributor

emiltin commented Jan 16, 2025 

    2025-01-16T13:51:04.699Z  47370  CZ+76000=101TC001    CZ+76000=101TC001    793f  Received StatusUpdate  {"cId": "CZ+76000=101TC001", "mId": "793faac5-2a8e-4693-b7d5-54abffa7575e", "mType": "rSMsg", "ntsOId": "", "sS": [{"n": "signalgroupstatus", "q": "recent", "s": "E2E2aaaaEEBBBaaaaaaaaa", "sCI": "S0001"}], "sTs": "2025-01-16T13:51:04.155Z", "type": "StatusUpdate", "xNId": ""}
    2025-01-16T13:51:04.701Z  47370  CZ+76000=101TC001    -                    -     Sent MessageAck for StatusUpdate 793f  {"mType":"rSMsg","type":"MessageAck","oMId":"793faac5-2a8e-4693-b7d5-54abffa7575e"}
    2025-01-16T13:51:04.708Z  47370  CZ+76000=101TC001    CZ+76000=101TC001    f91c  Sent StatusUnsubscribe  {"mType":"rSMsg","type":"StatusUnsubscribe","cId":"CZ+76000=101TC001","sS":[{"sCI":"S0001","n":"signalgroupstatus"}],"mId":"f91c2705-e124-47a2-bc29-516d4a2690ea","ntsOId":"","xNId":""}
    2025-01-16T13:51:04.713Z  47370  CZ+76000=101TC001    CZ+76000=101TC001    41d3  Rejected StatusUpdate message, no change for S0001 'signalgroupstatus'  {"cId": "CZ+76000=101TC001", "mId": "41d3f70b-2822-459c-971a-3cf6067a197b", "mType": "rSMsg", "ntsOId": "", "sS": [{"n": "signalgroupstatus", "q": "recent", "s": "E2E2aaaaEEBBBaaaaaaaaa", "sCI": "S0001"}], "sTs": "2025-01-16T13:51:04.156Z", "type": "StatusUpdate", "xNId": ""}

It looks like it sends a repeated status update, perhaps when receiving an unsubscribe?
@emiltin emiltin added RS4S Cross RS4S equipment Bug in equipment labels Jan 16, 2025
@emiltin
Copy link
Contributor Author

emiltin commented Jan 21, 2025 •
edited
Loading

Other examples:
https://github.com/rsmp-nordic/rsmp_validator/actions/runs/12886859003/job/35928343577#step:6:3725

    2025-01-21T12:32:00.095Z  40928  CZ+76000=101TC001    CZ+76000=101TC001    fe6f  Rejected StatusUpdate message, no change for S0001 'signalgroupstatus'  {"cId": "CZ+76000=101TC001", "mId": "fe6facaa-ce9d-4ad2-9e05-1eb7a816722f", "mType": "rSMsg", "ntsOId": "", "sS": [{"n": "signalgroupstatus", "q": "recent", "s": "E2E2aaaaEEBBBaaaaaaaaa", "sCI": "S0001"}], "sTs": "2025-01-21T12:31:59.788Z", "type": "StatusUpdate", "xNId": ""}
    2025-01-21T12:32:00.097Z  40928  CZ+76000=101TC001    -                    -     Sent MessageNotAck for StatusUpdate fe6f  {"mType":"rSMsg","type":"MessageNotAck","rea":"no change for S0001 'signalgroupstatus'","oMId":"fe6facaa-ce9d-4ad2-9e05-1eb7a816722f"}
    2025-01-21T12:32:00.099Z  40928  CZ+76000=101TC001    -                    -     Received MessageAck for StatusUnsubscribe 4deb  {"mType": "rSMsg", "oMId": "4deb851c-d13e-4d46-b045-3f24445c7595", "type": "MessageAck"}
    2025-01-21T12:32:00.105Z  40928  CZ+76000=101TC001    CZ+76000=101TC001    116b  Rejected StatusUpdate message, no change for S0001 'signalgroupstatus'  {"cId": "CZ+76000=101TC001", "mId": "116b9cca-2ee1-4c7e-b221-16fc46c6dd5f", "mType": "rSMsg", "ntsOId": "", "sS": [{"n": "signalgroupstatus", "q": "recent", "s": "E2E2aaaaEEBBBaaaaaaaaa", "sCI": "S0001"}], "sTs": "2025-01-21T12:31:59.788Z", "type": "StatusUpdate", "xNId": ""}
    2025-01-21T12:32:00.108Z  40928  CZ+76000=101TC001    -                    -     Sent MessageNotAck for StatusUpdate 116b  {"mType":"rSMsg","type":"MessageNotAck","rea":"no change for S0001 'signalgroupstatus'","oMId":"116b9cca-2ee1-4c7e-b221-16fc46c6dd5f"}

@pksoft72
Copy link

Other examples:

But if you subscribe with uRt=1, you should expect repeated status messages
20250121 123159.788340:3092618::DEBUG:RSMP:DoReceiveMessage::319::---> {"mType":"rSMsg","type":"StatusSubscribe","cId":"CZ+76000=101TC001","
sS":[{"sCI":"S0001","n":"signalgroupstatus","uRt":"1"}],"mId":"9dc6f08f-7913-4e54-a0f1-b5774d4d5264","ntsOId":"","xNId":""}

@emiltin
Copy link
Contributor Author

emiltin commented Jan 23, 2025 •
edited
Loading

Right, and the rsmp gem already skips the check for repeated status values if uRt is set:
https://github.com/rsmp-nordic/rsmp/blob/2d588802e2d7589a5d67635ef53d676728cd12cf/lib/rsmp/component_proxy.rb#L27

However the status update was received just after an unsubscribe:

Site::Traffic Light Controller Subscription can be turned on and off for S0001
    > Subscribe to status and wait for update
    2025-01-21T12:32:00.023Z  40928  CZ+76000=101TC001    -                    -     Collect 2954: Waiting for StatusUpdate/StatusResponse matching {"S0001"=>{"signalgroupstatus"=>:any}}
    2025-01-21T12:32:00.029Z  40928  CZ+76000=101TC001    CZ+76000=101TC001    9dc6  Sent StatusSubscribe  {"mType":"rSMsg","type":"StatusSubscribe","cId":"CZ+76000=101TC001","sS":[{"sCI":"S0001","n":"signalgroupstatus","uRt":"1"}],"mId":"9dc6f08f-7913-4e54-a0f1-b5774d4d5264","ntsOId":"","xNId":""}
    2025-01-21T12:32:00.031Z  40928  CZ+76000=101TC001    -                    -     Received MessageAck for StatusSubscribe 9dc6  {"mType": "rSMsg", "oMId": "9dc6f08f-7913-4e54-a0f1-b5774d4d5264", "type": "MessageAck"}
    2025-01-21T12:32:00.031Z  40928  CZ+76000=101TC001    -                    -     StatusSubscribe 9dc6 acknowledged, allowing repeated status values for [{"sCI"=>"S0001", "n"=>"signalgroupstatus", "uRt"=>"1"}]
    2025-01-21T12:32:00.080Z  40928  CZ+76000=101TC001    CZ+76000=101TC001    d168  Received StatusUpdate  {"cId": "CZ+76000=101TC001", "mId": "d168d73a-6b2b-4e73-abd4-c386e97e1d7d", "mType": "rSMsg", "ntsOId": "", "sS": [{"n": "signalgroupstatus", "q": "recent", "s": "E2E2aaaaEEBBBaaaaaaaaa", "sCI": "S0001"}], "sTs": "2025-01-21T12:31:59.788Z", "type": "StatusUpdate", "xNId": ""}
    2025-01-21T12:32:00.083Z  40928  CZ+76000=101TC001    -                    -     Sent MessageAck for StatusUpdate d168  {"mType":"rSMsg","type":"MessageAck","oMId":"d168d73a-6b2b-4e73-abd4-c386e97e1d7d"}
    2025-01-21T12:32:00.083Z  40928  CZ+76000=101TC001    -                    -     Status response d168 collect match {"sCI"=>"S0001", "n"=>"signalgroupstatus", "uRt"=>"1"}, item {"n"=>"signalgroupstatus", "q"=>"recent", "s"=>"E2E2aaaaEEBBBaaaaaaaaa", "sCI"=>"S0001"}
    2025-01-21T12:32:00.084Z  40928  CZ+76000=101TC001    -                    -     Collect 2954: Completed with {"S0001"=>{"signalgroupstatus"=>"E2E2aaaaEEBBBaaaaaaaaa"}}
    2025-01-21T12:32:00.090Z  40928  CZ+76000=101TC001    CZ+76000=101TC001    4deb  Sent StatusUnsubscribe  {"mType":"rSMsg","type":"StatusUnsubscribe","cId":"CZ+76000=101TC001","sS":[{"sCI":"S0001","n":"signalgroupstatus"}],"mId":"4deb851c-d13e-4d46-b045-3f24445c7595","ntsOId":"","xNId":""}
    2025-01-21T12:32:00.095Z  40928  CZ+76000=101TC001    CZ+76000=101TC001    fe6f  Rejected StatusUpdate message, no change for S0001 'signalgroupstatus'  {"cId": "CZ+76000=101TC001", "mId": "fe6facaa-ce9d-4ad2-9e05-1eb7a816722f", "mType": "rSMsg", "ntsOId": "", "sS": [{"n": "signalgroupstatus", "q": "recent", "s": "E2E2aaaaEEBBBaaaaaaaaa", "sCI": "S0001"}], "sTs": "2025-01-21T12:31:59.788Z", "type": "StatusUpdate", "xNId": ""}
    2025-01-21T12:32:00.097Z  40928  CZ+76000=101TC001    -                    -     Sent MessageNotAck for StatusUpdate fe6f  {"mType":"rSMsg","type":"MessageNotAck","rea":"no change for S0001 'signalgroupstatus'","oMId":"fe6facaa-ce9d-4ad2-9e05-1eb7a816722f"}
    2025-01-21T12:32:00.099Z  40928  CZ+76000=101TC001    -                    -     Received MessageAck for StatusUnsubscribe 4deb  {"mType": "rSMsg", "oMId": "4deb851c-d13e-4d46-b045-3f24445c7595", "type": "MessageAck"}
    2025-01-21T12:32:00.105Z  40928  CZ+76000=101TC001    CZ+76000=101TC001    116b  Rejected StatusUpdate message, no change for S0001 'signalgroupstatus'  {"cId": "CZ+76000=101TC001", "mId": "116b9cca-2ee1-4c7e-b221-16fc46c6dd5f", "mType": "rSMsg", "ntsOId": "", "sS": [{"n": "signalgroupstatus", "q": "recent", "s": "E2E2aaaaEEBBBaaaaaaaaa", "sCI": "S0001"}], "sTs": "2025-01-21T12:31:59.788Z", "type": "StatusUpdate", "xNId": ""}
    2025-01-21T12:32:00.108Z  40928  CZ+76000=101TC001    -                    -     Sent MessageNotAck for StatusUpdate 116b  {"mType":"rSMsg","type":"MessageNotAck","rea":"no change for S0001 'signalgroupstatus'","oMId":"116b9cca-2ee1-4c7e-b221-16fc46c6dd5f"}
    Passed

I think the problem is that a status update is send after the unsubscribe. However the status is receive before the unsubscribe is acknowledged. Probably the status update was already in flight when the unsubscribe was received.

When unsubscribing, the subscription list in the rsmp gem is updated to remove the particular status:
https://github.com/rsmp-nordic/rsmp/blob/2d588802e2d7589a5d67635ef53d676728cd12cf/lib/rsmp/site_proxy.rb#L248

From that point, a status update will be checked for repeat values.

I think the correct fix is to not update the subscription list in the rsmp gem until the unsubscribe is acknowledged.

In the latest nighty test, this issue did not show up. Perhaps it's intermittet, depending on timing.

@pksoft72
Copy link

I think the correct fix is to not update the subscription list in the rsmp gem until the unsubscribe is acknowledged.

I agree.

@emiltin emiltin mentioned this issue Jan 23, 2025
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
equipment Bug in equipment RS4S Cross RS4S
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@emiltin @pksoft72