Hi,
There seems to be some issue with Motorola ARS registrations going through OpenSpot 2 and 3 with latest firmware versions.
I have two radios, DP4801e and DM4601e which are both experiencing the same issue. When going through an MMDVM running dmrhost, the BM master log is as follows:
2024-05-15T12:12:55.939250+03:00 BM-2441 Master 2441[3293715]: New session a56c274f-0702-462d-9f6d-84b1410582c7 of MMDVM Host system 244304310 (6cd3a801-71a1-43d7-85eb-131098da5286) at slot 0
2024-05-15T12:12:56.143598+03:00 BM-2441 Master 2441[3293715]: Session a56c274f-0702-462d-9f6d-84b1410582c7 marked as Private Control Block from 2443043 to 244999, expect 0 block(s)
2024-05-15T12:12:56.143748+03:00 BM-2441 Master 2441[3293715]: *** Registration Service: Registration of ID 2443043 using Motorola ARS
2024-05-15T12:12:56.144082+03:00 BM-2441 Master 2441[3293715]: Added route to MMDVM Host system 244304310 (6cd3a801-71a1-43d7-85eb-131098da5286) at slot 0 (locked) by SpiderStore (session cb8ea163-eaa3-45aa-a6d3-0c2601d7ed90)
2024-05-15T12:12:56.145009+03:00 BM-2441 Master 2441[3293715]: Session cb8ea163-eaa3-45aa-a6d3-0c2601d7ed90 marked as Private Control Block from 244999 to 2443043, expect 0 block(s)
2024-05-15T12:12:56.145559+03:00 BM-2441 Master 2441[3293715]: *** Location Service: Requesting triggered reports for ID 2443043 (interval is 120 seconds)
2024-05-15T12:12:56.158888+03:00 BM-2441 Master 2441[3293715]: Added route to MMDVM Host system 244304310 (6cd3a801-71a1-43d7-85eb-131098da5286) at slot 0 (locked) by SpiderStore (session c7d906e6-8055-4b0e-8180-ca4dfa7804ac)
2024-05-15T12:12:56.159018+03:00 BM-2441 Master 2441[3293715]: Session c7d906e6-8055-4b0e-8180-ca4dfa7804ac marked as Private Control Block from 244999 to 2443043, expect 4 block(s)
2024-05-15T12:12:56.220321+03:00 BM-2441 Master 2441[3293715]: Added route to MMDVM Host system 244304310 (6cd3a801-71a1-43d7-85eb-131098da5286) at slot 0 (locked) by SpiderStore (session c7d906e6-8055-4b0e-8180-ca4dfa7804ac)
2024-05-15T12:12:56.220578+03:00 BM-2441 Master 2441[3293715]: Session c7d906e6-8055-4b0e-8180-ca4dfa7804ac marked as Private Data Call from 244999 to 2443043, expect 3 block(s)
2024-05-15T12:12:58.206290+03:00 BM-2441 Master 2441[3293715]: New session 4936e13b-db1e-409c-b688-2df5e19f6ef2 of MMDVM Host system 244304310 (6cd3a801-71a1-43d7-85eb-131098da5286) at slot 0
2024-05-15T12:12:58.411459+03:00 BM-2441 Master 2441[3293715]: Session 4936e13b-db1e-409c-b688-2df5e19f6ef2 marked as Private Data Call from 2443043 to 244999, expect 0 block(s)
2024-05-15T12:13:01.151360+03:00 BM-2441 Master 2441[3293715]: New session c66716ea-f61f-4c7d-998a-fffaf9d17b8d of MMDVM Host system 244304310 (6cd3a801-71a1-43d7-85eb-131098da5286) at slot 0
2024-05-15T12:13:01.352992+03:00 BM-2441 Master 2441[3293715]: Session c66716ea-f61f-4c7d-998a-fffaf9d17b8d marked as Private Control Block from 2443043 to 0, expect 0 block(s)
2024-05-15T12:13:03.490454+03:00 BM-2441 Master 2441[3293715]: New session c9ab3e87-c471-47a3-b248-db3e0dd9910e of MMDVM Host system 244304310 (6cd3a801-71a1-43d7-85eb-131098da5286) at slot 0
2024-05-15T12:13:03.694199+03:00 BM-2441 Master 2441[3293715]: Session c9ab3e87-c471-47a3-b248-db3e0dd9910e marked as Private Control Block from 2443043 to 0, expect 0 block(s)
After this, position reports start coming in normally. But doing the same with either OpenSpot 2 or 3 results in the following:
2024-05-15T12:15:52.324962+03:00 BM-2441 Master 2441[3293715]: New session 63328e85-7881-4964-9706-ec8cf2ca3808 of Homebrew Repeater system 244304302 (d3f24e07-56ce-4cdf-9504-ffa6f0fc0c9d) at slot 0
2024-05-15T12:15:52.531693+03:00 BM-2441 Master 2441[3293715]: Session 63328e85-7881-4964-9706-ec8cf2ca3808 marked as Private Control Block from 2443043 to 244999, expect 0 block(s)
2024-05-15T12:15:52.531900+03:00 BM-2441 Master 2441[3293715]: *** Registration Service: Registration of ID 2443043 using Motorola ARS
2024-05-15T12:15:52.532904+03:00 BM-2441 Master 2441[3293715]: Added route to Homebrew Repeater system 244304302 (d3f24e07-56ce-4cdf-9504-ffa6f0fc0c9d) at slot 0 (locked) by SpiderStore (session 8fc602ae-1f29-49c2-a1d1-820757ace8f8)
2024-05-15T12:15:52.533068+03:00 BM-2441 Master 2441[3293715]: Session 8fc602ae-1f29-49c2-a1d1-820757ace8f8 marked as Private Control Block from 244999 to 2443043, expect 0 block(s)
2024-05-15T12:15:52.533367+03:00 BM-2441 Master 2441[3293715]: *** Location Service: Requesting triggered reports for ID 2443043 (interval is 120 seconds)
2024-05-15T12:15:52.574451+03:00 BM-2441 Master 2441[3293715]: Added route to Homebrew Repeater system 244304302 (d3f24e07-56ce-4cdf-9504-ffa6f0fc0c9d) at slot 0 (locked) by SpiderStore (session 728e82cb-eb25-473e-81f2-e10b03399981)
2024-05-15T12:15:52.574719+03:00 BM-2441 Master 2441[3293715]: Session 728e82cb-eb25-473e-81f2-e10b03399981 marked as Private Control Block from 244999 to 2443043, expect 4 block(s)
2024-05-15T12:15:52.635704+03:00 BM-2441 Master 2441[3293715]: Added route to Homebrew Repeater system 244304302 (d3f24e07-56ce-4cdf-9504-ffa6f0fc0c9d) at slot 0 (locked) by SpiderStore (session 728e82cb-eb25-473e-81f2-e10b03399981)
2024-05-15T12:15:52.635897+03:00 BM-2441 Master 2441[3293715]: Session 728e82cb-eb25-473e-81f2-e10b03399981 marked as Private Data Call from 244999 to 2443043, expect 3 block(s)
2024-05-15T12:15:53.455790+03:00 BM-2441 Master 2441[3293715]: New session 157144ac-6724-4684-99c1-c9fa7346c96c of Homebrew Repeater system 244304302 (d3f24e07-56ce-4cdf-9504-ffa6f0fc0c9d) at slot 0
2024-05-15T12:15:53.667317+03:00 BM-2441 Master 2441[3293715]: Session 157144ac-6724-4684-99c1-c9fa7346c96c marked as Private Data Call from 2443043 to 244999, expect 1 block(s)
2024-05-15T12:15:53.713042+03:00 BM-2441 Master 2441[3293715]: *** Recipient has requested to repeat selected blocks (2443043 -> 244999)
2024-05-15T12:15:53.718586+03:00 BM-2441 Master 2441[3293715]: Added route to Homebrew Repeater system 244304302 (d3f24e07-56ce-4cdf-9504-ffa6f0fc0c9d) at slot 0 (locked) by SpiderStore (session ad49188e-7bb4-4729-8290-1d7cae06c1b2)
2024-05-15T12:15:53.719172+03:00 BM-2441 Master 2441[3293715]: Session ad49188e-7bb4-4729-8290-1d7cae06c1b2 marked as Private Control Block from 244999 to 2443043, expect 3 block(s)
2024-05-15T12:15:53.780072+03:00 BM-2441 Master 2441[3293715]: Added route to Homebrew Repeater system 244304302 (d3f24e07-56ce-4cdf-9504-ffa6f0fc0c9d) at slot 0 (locked) by SpiderStore (session ad49188e-7bb4-4729-8290-1d7cae06c1b2)
2024-05-15T12:15:53.780618+03:00 BM-2441 Master 2441[3293715]: Session ad49188e-7bb4-4729-8290-1d7cae06c1b2 marked as Private Data Call from 244999 to 2443043, expect 2 block(s)
2024-05-15T12:15:58.766607+03:00 BM-2441 Master 2441[3293715]: Response timed out (attempt 2, type 3 / 4, 244999 -> 2443043)
2024-05-15T12:15:58.767527+03:00 BM-2441 Master 2441[3293715]: Added route to Homebrew Repeater system 244304302 (d3f24e07-56ce-4cdf-9504-ffa6f0fc0c9d) at slot 0 (locked) by SpiderStore (session d8dc2653-3de1-4eb0-a8de-05edf4b02c85)
2024-05-15T12:15:58.768010+03:00 BM-2441 Master 2441[3293715]: Session d8dc2653-3de1-4eb0-a8de-05edf4b02c85 marked as Private Control Block from 244999 to 2443043, expect 3 block(s)
2024-05-15T12:15:58.829250+03:00 BM-2441 Master 2441[3293715]: Added route to Homebrew Repeater system 244304302 (d3f24e07-56ce-4cdf-9504-ffa6f0fc0c9d) at slot 0 (locked) by SpiderStore (session d8dc2653-3de1-4eb0-a8de-05edf4b02c85)
2024-05-15T12:15:58.829741+03:00 BM-2441 Master 2441[3293715]: Session d8dc2653-3de1-4eb0-a8de-05edf4b02c85 marked as Private Data Call from 244999 to 2443043, expect 2 block(s)
2024-05-15T12:16:03.817233+03:00 BM-2441 Master 2441[3293715]: Response timed out (attempt 3, type 3 / 4, 244999 -> 2443043)
Looking at this, it seems there is a problem with the response from ARS at 244999 reaching the radio when using OpenSpot. It also looks like the radio is attempting registration multiple times when going through OpenSpot, while through MMDVM/dmrhost the registration succeeds the first time.
dmrcalltracker[0]: prv data call started, dst: 468295 src: 2355232 id: 6a709206ae5e5e46
nvmm-csd: looking up id 468295 type 0
nvmm-csd: no csd
nvmm-csd: looking up id 2355232 type 0
nvmm-csd: no csd
dmrcalltracker[0]: call ended, dur 0.0s ber 3.4% loss 0.0% rssi -43
homebrew-dmr [0]: call stopped
dmrcalltracker[0]: prv data call started, dst: 2294717 src: 507649 id: 3ee6fa72a058a422
nvmm-csd: looking up id 2294717 type 0
nvmm-csd: no csd
nvmm-csd: looking up id 507649 type 0
nvmm-csd: no csd
homebrew: instantly sending data to modem
dmrcalltracker[0]: call ended, dur 0.0s ber 0.0% loss 0.0% rssi 0
dmr-sms: call from network, but we don't intercept network msgs
dmrcalltracker[0]: prv data call started, dst: 2443043 src: 244999 id: e8166afcc4540e64
nvmm-csd: looking up id 2443043 type 0
nvmm-csd: no csd
nvmm-csd: looking up id 244999 type 0
nvmm-csd: no csd
dmr-sms: sms call is not ongoing, ignoring rate 3/4 data
dmr-sms: sms call is not ongoing, ignoring rate 3/4 data
dmr-sms: sms call is not ongoing, ignoring rate 3/4 data
dmrcalltracker[0]: prv data call started, dst: 0 src: 0 id: a822e0fa8480fe82
nvmm-csd: looking up id 0 type 0
nvmm-csd: no csd
nvmm-csd: looking up id 0 type 0
nvmm-csd: no csd
dmr-sms: sms call is not ongoing, ignoring rate 1/2 data
httpcln: received 5364868 bytes (46% 794s)
homebrew: ping sent
homebrew: pong received
dmrcalltracker[0]: call ended (timeout), dur 3.2s ber 0.0% loss 0.0% rssi 0
httpcln: received 5379792 bytes (46% 796s)
dmrcalltracker[0]: call ended (timeout), dur 6.0s ber 0.0% loss 0.0% rssi -85
gs-cmd: status parse error
gs: association check failed, retrying
gs: association check retry ok
httpcln: received 5391796 bytes (46% 800s)
homebrew: ping sent
homebrew: pong received
httpcln: received 5411100 bytes (46% 802s)
dmr-sms: call from network, but we don't intercept network msgs
dmrcalltracker[0]: prv data call started, dst: 2443043 src: 244999 id: f2d29c7894e67a74
nvmm-csd: looking up id 2443043 type 0
nvmm-csd: no csd
nvmm-csd: looking up id 244999 type 0
nvmm-csd: no csd
dmr-sms: sms call is not ongoing, ignoring rate 3/4 data
dmr-sms: sms call is not ongoing, ignoring rate 3/4 data
dmr-sms: sms call is not ongoing, ignoring rate 3/4 data
dmrcalltracker[0]: prv data call started, dst: 244999 src: 2443043 id: a29834e29eec3636
nvmm-csd: looking up id 244999 type 0
nvmm-csd: no csd
nvmm-csd: looking up id 2443043 type 0
nvmm-csd: no csd
dmr-sms: sms call is not ongoing, ignoring rate 1/2 data
homebrew: received seqnum diff 252
homebrew: got duplicated frame on tc0, dropping
dmr-sms: sms call is not ongoing, ignoring rate 3/4 data
dmr-sms: sms call is not ongoing, ignoring rate 3/4 data
dmr-sms: sms call is not ongoing, ignoring rate 3/4 data
httpcln: received 5430404 bytes (46% 804s)
httpcln: received 5445328 bytes (46% 806s)
dmrcalltracker[0]: call ended (timeout), dur 3.1s ber 0.4% loss 0.0% rssi -45
dmrcalltracker[0]: call ended (timeout), dur 4.5s ber 0.0% loss 0.0% rssi 0
homebrew: ping sent
homebrew: pong received
httpcln: received 5457332 bytes (46% 809s)
httpcln: received 5476636 bytes (47% 811s)
The strange output regarding ID numbers is probably due to CSBK Data setting being active, this also seems to produce notifications about CC mismatches, although as per the BM master log, the data calls reach the master and ARS service at 244999 just fine.
What I'm concerned about are these:
homebrew: received seqnum diff 252
homebrew: got duplicated frame on tc0, dropping
I remember we debugged a similar issue with HA2NON a couple years prior on the same hardware. If I recall correctly, the issue that time had something to do with how BM is issuing sequence numbers to data call frames (or something to that end, I'm not an expert). The issue was resolved with an experimental firmware, and later integrated into the official fw release. Perhaps this is something similar?
To me this looks like the data call from BM ARS at 244999 is not reaching the radio due to OpenSpot firmware dropping frames from it. BM ARS always sends its responses as confirmed data and it seems the data call gets dropped/retried, finally timing out.
