OP25 Metadata Rarely Shows Radio IDs

ASTRO_Man

Member
Premium Subscriber
Joined
Mar 8, 2010
Messages
267
I'm currently experiencing an issue with my OP25 setup where I'm unable to receive radio IDs consistently. The problem is that I am not consistently seeing radio IDs in the metadata output. Sometimes an ID appears alongside the TGID alias, but most of the time it is just the TGID alias. This is happening despite receiving clear audio and other transmission data without any issues. I wanted to see if anyone had any insight on what could be causing the inconsistencies.

My Setup:
Software: boatbod/OP25
SDR Device: Airspy Mini
System: Ubuntu Server Linux
Monitoring: P25 Phase 1

My .json for multi_rx:
Code:
{
    "channels": [
        {
            "name": "feed1",
            "device": "sdr0",
            "trunking_sysname": "system1",
            "meta_stream_name": "feed1",
            "demod_type": "cqpsk",
            "cqpsk_tracking": true,
            "tracking_threshold": 120,
            "tracking_feedback": 0.75,
            "destination": "udp://127.0.0.1:9001",
            "excess_bw": 0.2,
            "filter_type": "rc",
            "if_rate": 24000,
            "plot": "",
            "symbol_rate": 4800,
            "enable_analog": "off",
            "blacklist": "",
            "whitelist": "feed1.wlist",
            "crypt_keys": "keys.json"
        },
        {
            "name": "feed2",
            "device": "sdr0",
            "trunking_sysname": "system1",
            "meta_stream_name": "feed2",
            "demod_type": "cqpsk",
            "cqpsk_tracking": true,
            "tracking_threshold": 120,
            "tracking_feedback": 0.75,
            "destination": "udp://127.0.0.1:9002",
            "excess_bw": 0.2,
            "filter_type": "rc",
            "if_rate": 24000,
            "plot": "",
            "symbol_rate": 4800,
            "enable_analog": "off",
            "blacklist": "",
            "whitelist": "feed2.wlist",
            "crypt_keys": "keys.json"
        }
    ],
    "devices": [
        {
            "args": "airspy",
            "frequency" : 852225000,
            "gains": "LNA:15,MIX:15,IF:8",
            "gain_mode": true,
            "name": "sdr0",
            "offset": 0,
            "ppm": 0.0,
            "rate": 6000000,
            "usable_bw_pct": 0.95,
            "tunable": false
        }
    ],
    "trunking": {
        "module": "tk_p25.py",
        "chans": [
            {
                "nac": "0x0",
                "sysname": "system1",
                "control_channel_list": "855.8150,858.0775,853.1575",
                "whitelist": "",
                "blacklist": "",
                "tgid_tags_file": "system1_tgids.tsv",
                "rid_tags_file": "system1_rids.tsv",
                "tdma_cc": false,
                "crypt_behavior": 2
            }
        ]
    },
    "metadata": {
        "module": "icemeta.py",
        "streams": [
            {
                "stream_name": "feed1",
                "meta_format_idle": "Scanning...",
                "meta_format_tgid": "[%TGID%]",
                "meta_format_tag":  "%TAG%",
                "meta_format_rid":  "[%RID%]",
                "meta_format_rtag": "[%RTAG%]",
                "icecastServerAddress": "127.0.0.1:8000",
                "icecastMountpoint": "feed1",
                "icecastMountExt": ".xspf",
                "icecastPass": "redacted",
                "delay": 0.0
            },
            {
                "stream_name": "feed2",
                "meta_format_idle": "Scanning...",
                "meta_format_tgid": "[%TGID%]",
                "meta_format_tag":  "%TAG%",
                "meta_format_rid":  "[%RID%]",
                "meta_format_rtag": "[%RTAG%]",
                "icecastServerAddress": "127.0.0.1:8000",
                "icecastMountpoint": "feed2",
                "icecastMountExt": ".xspf",
                "icecastPass": "redacted",
                "delay": 0.0
            }
        ]
    },
    "audio": {
        "module": "audio.py",
        "instances": [
            {
                "instance_name": "audio0",
                "device_name": "pulse",
                "udp_port": 9001,
                "audio_gain": 2.0,
                "number_channels": 1
            },
            {
                "instance_name": "audio1",
                "device_name": "pulse",
                "udp_port": 9002,
                "audio_gain": 2.0,
                "number_channels": 1
            }
        ]
    },
    "terminal": {
        "module": "terminal.py",
        "terminal_type": "curses",
        "#terminal_type": "http:127.0.0.1:8080",
        "curses_plot_interval": 0.1,
        "http_plot_interval": 1.0,
        "http_plot_directory": "../www/images",
        "tuning_step_large": 1200,
        "tuning_step_small": 100,
        "default_channel": ""
    }
}
 

boatbod

Member
Joined
Mar 3, 2007
Messages
3,409
Location
Talbot Co, MD
Has it always appeared this way for the system you are monitoring?

OP25 extracts the RID from several different places in the P25 protocol. On a phase 1 system, RID is found in the HDU, LDU1 LCW, and optionally TDU15 LCW. If the HDU is missed - which is more often than not the case with op25 due to tuning latency - the RID has to come from LDU1 which may take a while to arrive. If the transmission is short, it's entirely possible that the call will have ended before the RID is received and percolates it's way to the terminal during one of the polling update cycles.

If you want to study what's going on, look at the logs (running at -v 1) and see if a non-zero RID is listed at the time the call initiates.
Code:
01/03/24 05:58:00.299444 [0] voice update:  tg(11501), rid(2619005), freq(771.718750), slot(0), prio(1)
01/03/24 06:01:38.848771 [0] voice update:  tg(11504), rid(2600371), freq(773.593750), slot(1), prio(3)
01/03/24 06:01:43.427599 [0] voice update:  tg(11504), rid(2619005), freq(773.593750), slot(0), prio(3)
01/03/24 06:10:28.793004 [0] voice update:  tg(11504), rid(2600162), freq(773.593750), slot(1), prio(3)
01/03/24 06:10:32.926068 [0] voice update:  tg(11504), rid(2619005), freq(773.593750), slot(1), prio(3)
01/03/24 06:10:39.004167 [0] voice update:  tg(11504), rid(2619005), freq(773.593750), slot(1), prio(3)
If the RIDs are coming through at 0, turn logging up to -v 11 and dive into the protocol to see where/when the RID does get known.
 

ASTRO_Man

Member
Premium Subscriber
Joined
Mar 8, 2010
Messages
267
Has it always appeared this way for the system you are monitoring?

OP25 extracts the RID from several different places in the P25 protocol. On a phase 1 system, RID is found in the HDU, LDU1 LCW, and optionally TDU15 LCW. If the HDU is missed - which is more often than not the case with op25 due to tuning latency - the RID has to come from LDU1 which may take a while to arrive. If the transmission is short, it's entirely possible that the call will have ended before the RID is received and percolates it's way to the terminal during one of the polling update cycles.

If you want to study what's going on, look at the logs (running at -v 1) and see if a non-zero RID is listed at the time the call initiates.
Code:
01/03/24 05:58:00.299444 [0] voice update:  tg(11501), rid(2619005), freq(771.718750), slot(0), prio(1)
01/03/24 06:01:38.848771 [0] voice update:  tg(11504), rid(2600371), freq(773.593750), slot(1), prio(3)
01/03/24 06:01:43.427599 [0] voice update:  tg(11504), rid(2619005), freq(773.593750), slot(0), prio(3)
01/03/24 06:10:28.793004 [0] voice update:  tg(11504), rid(2600162), freq(773.593750), slot(1), prio(3)
01/03/24 06:10:32.926068 [0] voice update:  tg(11504), rid(2619005), freq(773.593750), slot(1), prio(3)
01/03/24 06:10:39.004167 [0] voice update:  tg(11504), rid(2619005), freq(773.593750), slot(1), prio(3)
If the RIDs are coming through at 0, turn logging up to -v 11 and dive into the protocol to see where/when the RID does get known.

Thanks boatbod for your assistance. I did -v 1 before and noticed the RID got picked up very shortly after OP25 received the transmission. I’ll do this again later (with -v 11) and post my results. I guess my goal would be to see if OP25 would poll more frequently for the RID, but I’ll see what my results are first.
 

MTL_Emergencies

Member++
Database Admin
Joined
Sep 6, 2019
Messages
143
Location
Quebec, Canada
From my experience, OP25 has issues with decoding RIDs on Phase II patched TGs (with simulcast), but that's also a common issue with other decoders and Uniden scanners. I wouldn't think it's a simulcast issue as I don't have this problem with non-patched TGs (even on Phase II) but I recorded baseband with DSD Fastlane if you want to check it out: P25-Phase-II-Voice.wav
 

boatbod

Member
Joined
Mar 3, 2007
Messages
3,409
Location
Talbot Co, MD
Thanks boatbod for your assistance. I did -v 1 before and noticed the RID got picked up very shortly after OP25 received the transmission. I’ll do this again later (with -v 11) and post my results. I guess my goal would be to see if OP25 would poll more frequently for the RID, but I’ll see what my results are first.
Terminal update time is about 1Hz.
 

lwvmobile

DSD-FME
Joined
Apr 26, 2020
Messages
1,297
Location
Lafayette County, FL
From my experience, OP25 has issues with decoding RIDs on Phase II patched TGs (with simulcast), but that's also a common issue with other decoders and Uniden scanners. I wouldn't think it's a simulcast issue as I don't have this problem with non-patched TGs (even on Phase II) but I recorded baseband with DSD Fastlane if you want to check it out: P25-Phase-II-Voice.wav
What's the WACN/SYS/CC values on that Phase 2 sample? Can't descramble it if there isn't a NET_STS_BCST on the sample.
 

lwvmobile

DSD-FME
Joined
Apr 26, 2020
Messages
1,297
Location
Lafayette County, FL
Yeah, patch systems always have some thing going on in the RID for the user. Often, has been my experience, that the MAC_PTT will have a RID of 0, and then fill in when the SACCH field updates the voice channel user parameters, sometimes, that's pretty fast like in this example you uploaded, but other times, you have to wait a few superframes depending on other call activity and channel activity, and by then, the call can be over. Probably my own little personal annoyance with P25 is that the HDU/TDU and MAC_PTT/MAC_END_PTT allows a 0 for the RID, unlike DMR, which always has the radio ID for the SRC.

Code:
12:02:11        P25p2 LCH 1  MAC_PTT 
 VCH 1 - TG 50004 SRC 0
12:02:11        P25p2 LCH 0  MAC_IDLE
12:02:11        P25p2 LCH 1  MAC_PTT 
 VCH 1 - TG 50004 SRC 0
12:02:11        P25p2 SACCH  MAC_ACTIVE
 VCH 1 - Super Group 50004 SRC 702099 MFID90 Group Regroup Voice
12:02:11 Sync: +P25p2 SISCH  WACN [1490E] SYS [CFF] NAC [CF1]

Harris can get worse though, they do the same thing with with the SRC=0, but also alternate between optionally a Talker Alias, GPS, and then the voice channel user update in SACCH fields, making you wait a while for a RID. On short calls, the call is over and you never have a valid RID/UID/WUID.

This sample shows no valid SRC value conveyed due to its bevity (probably a "10-4" message, or finger slipped off the PTT)
Code:
12:11:50        P25p2 LCH 1  MAC_PTT 
 VCH 1 - TG 64808 SRC 0 <---SRC = 0
         ALG ID: 0x84 KEY ID: 0x0001 MI: 0xD63B7D84666A7987 MPTT
      ALG ID: 0x84 KEY ID: 0x01 MI(128): 0xD63B7D84666A7987571F250EAD7B4451
12:11:50        P25p2 LCCH   MAC_SIGNAL
 System Service Broadcast - Abbreviated
  TWV: 00 SSA: 0C2C00; SSS: 0C2C00; RPL: 01
12:11:50        P25p2 LCH 1  4V 1
12:11:50 Sync: +P25p2 SISCH  WACN [91F14] SYS [2D7] NAC [01A]
12:11:50        P25p2 LCCH   MAC_SIGNAL
 Group Voice Channel Grant Update - Implicit
  Channel 1 [82B9] Group 1 [64808][FD28]
  Frequency [855.362500] MHz
  Channel 2 [82B9] Group 2 [64808][FD28]
  Frequency [855.362500] MHz
12:11:50        P25p2 LCH 1  4V 2
12:11:50        P25p2 LCCH   MAC_SIGNAL
 MFID A4 (Harris) Group Regroup Explicit Encryption Command
 Patch Active; SSN: 08; SG: 64808; KEY: 0001; ALG: 84;
  WGID: 62773; WGID: 62774;
12:11:50        P25p2 LCH 1  4V 3
12:11:50 Sync: +P25p2 SISCH  WACN [91F14] SYS [2D7] NAC [01A]
12:11:50        P25p2 SACCH  MAC_ACTIVE
 MFID A4 (Harris); VCH 1; TG: 64808; SRC: 0; Talker Alias: FL-DCC-0     
12:11:50        P25p2 LCCH   MAC_SIGNAL
 Adjacent Status Broadcast - Abbreviated
  LRA [2B] RFSS[043] SITE [043] SYSID [2D7] CHAN-T [8304] SSC [70]
   Up to Date (Correct) Valid RFSS Connection Active
  Frequency [855.837500] MHz
12:11:50        P25p2 LCCH   MAC_SIGNAL
 MFID A4 (Harris); Res: 0; Len: 18; Opcode: 01; 0F110DFFFFFFFFFFFFFFFFFFFFFFFF
12:11:50        P25p2 LCH 1  4V 4
12:11:50 Sync: +P25p2 SISCH  WACN [91F14] SYS [2D7] NAC [01A]
12:11:50        P25p2 LCCH   MAC_SIGNAL
 MFID A4 (Harris) Group Regroup Explicit Encryption Command
 Patch Active; SSN: 09; SG: 64809; KEY: 0001; ALG: 84;
  WGID: 62775; WGID: 62776;
12:11:50        P25p2 LCH 1  2V
 VCH 1 - ALG ID: 0x84 KEY ID: 0x0001 MI: 0x571F250EAD7B4451 ESSB
      ALG ID: 0x84 KEY ID: 0x01 MI(128): 0x571F250EAD7B4451822767B6C459BE7F
12:11:50        P25p2 LCCH   MAC_SIGNAL
 MFID A4 (Harris); Res: 0; Len: 7; Opcode: 0F; 0A44800A
12:11:50        P25p2 LCH 1  4V 1
12:11:50 Sync: +P25p2 SISCH  WACN [91F14] SYS [2D7] NAC [01A]
12:11:50        P25p2 LCCH   MAC_SIGNAL
 RFSS Status Broadcast - Implicit
  LRA [1A] SYSID [2D7] RFSS ID [026] SITE ID [026] CHAN [82B8] SSC [70]
  Frequency [855.362500] MHz
12:11:50        P25p2 LCH 1  4V 2
12:11:50        P25p2 LCCH   MAC_SIGNAL
 MFID A4 (Harris) Group Regroup Explicit Encryption Command
 Patch Active; SSN: 01; SG: 64201; KEY: 0001; ALG: 84;
  WGID: 62208; WGID: 62464; WGID: 62976; WGID: 62720;
12:11:50        P25p2 LCH 1  MAC_END_PTT
 VCH 1 - TG 64808 SRC 0
 

ASTRO_Man

Member
Premium Subscriber
Joined
Mar 8, 2010
Messages
267
Here are my stderr.2 logs. I monitored for a few minutes during some of the -v 11 transmissions and did not see any RIDs come through the metadata. The 400 errors I am assuming are because I stopped liquidsoap at the time.

-v 1
Code:
01/04/24 13:12:42.425025 [0] voice update:  tg(23507), rid(1359002), freq(852.337500), slot(-), prio(1)
01/04/24 13:12:42.799714 [0] voice update:  tg(23507), rid(0), freq(852.337500), slot(-), prio(1)
01/04/24 13:13:05.373881 [0] voice update:  tg(23507), rid(0), freq(852.337500), slot(-), prio(1)
01/04/24 13:13:05.670420 [0] voice update:  tg(23507), rid(0), freq(852.337500), slot(-), prio(1)
01/04/24 13:13:05.974714 [0] voice update:  tg(23507), rid(0), freq(852.337500), slot(-), prio(1)
01/04/24 13:13:06.350107 [0] voice update:  tg(23507), rid(0), freq(852.337500), slot(-), prio(1)
01/04/24 13:47:01.396670 [0] voice update:  tg(23569), rid(1353720), freq(852.337500), slot(-), prio(3)
01/04/24 13:47:01.923002 [0] voice update:  tg(23569), rid(0), freq(852.337500), slot(-), prio(3)
01/04/24 13:47:06.498542 [0] voice update:  tg(23569), rid(0), freq(852.337500), slot(-), prio(3)
01/04/24 13:47:06.873458 [0] voice update:  tg(23569), rid(0), freq(852.337500), slot(-), prio(3)
01/04/24 13:47:07.027238 [0] voice update:  tg(23569), rid(0), freq(852.337500), slot(-), prio(3)
01/04/24 13:47:07.321275 [0] voice update:  tg(23569), rid(0), freq(852.337500), slot(-), prio(3)
01/04/24 13:48:29.374288 [0] voice update:  tg(23569), rid(1353720), freq(851.762500), slot(-), prio(3)
01/04/24 13:48:29.812982 [0] voice update:  tg(23569), rid(0), freq(851.762500), slot(-), prio(3)
01/04/24 13:48:31.544738 [0] voice update:  tg(23569), rid(0), freq(851.762500), slot(-), prio(3)
01/04/24 13:48:31.848833 [0] voice update:  tg(23569), rid(0), freq(851.762500), slot(-), prio(3)
01/04/24 13:48:32.144179 [0] voice update:  tg(23569), rid(0), freq(851.762500), slot(-), prio(3)
01/04/24 13:48:32.368946 [0] voice update:  tg(23569), rid(0), freq(851.762500), slot(-), prio(3)
01/04/24 13:48:32.663170 [0] voice update:  tg(23569), rid(0), freq(851.762500), slot(-), prio(3)
01/04/24 13:51:14.071709 [0] voice update:  tg(23576), rid(1353146), freq(851.762500), slot(-), prio(2)
01/04/24 13:51:14.517507 [0] voice update:  tg(23576), rid(0), freq(851.762500), slot(-), prio(2)
01/04/24 13:51:17.371012 [0] voice update:  tg(23576), rid(0), freq(851.762500), slot(-), prio(2)
01/04/24 13:51:17.736629 [0] voice update:  tg(23576), rid(0), freq(851.762500), slot(-), prio(2)
01/04/24 13:51:18.052873 [0] voice update:  tg(23576), rid(0), freq(851.762500), slot(-), prio(2)
01/04/24 13:51:18.418765 [0] voice update:  tg(23576), rid(0), freq(851.762500), slot(-), prio(2)
01/04/24 13:51:26.298242 [0] voice update:  tg(23577), rid(1353146), freq(851.662500), slot(-), prio(2)
01/04/24 13:51:26.453552 [0] voice update:  tg(23577), rid(0), freq(851.662500), slot(-), prio(2)
01/04/24 13:51:26.739842 [0] voice update:  tg(23577), rid(0), freq(851.662500), slot(-), prio(2)
01/04/24 13:51:29.300460 [0] voice update:  tg(23577), rid(0), freq(851.662500), slot(-), prio(2)
01/04/24 13:51:29.594176 [0] voice update:  tg(23577), rid(0), freq(851.662500), slot(-), prio(2)
01/04/24 13:51:29.897896 [0] voice update:  tg(23577), rid(0), freq(851.662500), slot(-), prio(2)
01/04/24 13:51:30.192323 [0] voice update:  tg(23577), rid(0), freq(851.662500), slot(-), prio(2)
01/04/24 13:51:30.496573 [0] voice update:  tg(23577), rid(0), freq(851.662500), slot(-), prio(2)
01/04/24 13:53:07.090685 [0] voice update:  tg(23507), rid(1359002), freq(851.662500), slot(-), prio(1)
01/04/24 13:53:07.243155 [0] voice update:  tg(23507), rid(0), freq(851.662500), slot(-), prio(1)
01/04/24 13:53:07.619652 [0] voice update:  tg(23507), rid(0), freq(851.662500), slot(-), prio(1)
01/04/24 13:53:25.693836 [0] voice update:  tg(23507), rid(0), freq(851.662500), slot(-), prio(1)
01/04/24 13:53:25.997971 [0] voice update:  tg(23507), rid(0), freq(851.662500), slot(-), prio(1)
01/04/24 13:53:26.364816 [0] voice update:  tg(23507), rid(0), freq(851.662500), slot(-), prio(1)
01/04/24 13:53:35.738914 [0] voice update:  tg(23507), rid(1359002), freq(851.387500), slot(-), prio(1)
01/04/24 13:53:36.123909 [0] voice update:  tg(23507), rid(0), freq(851.387500), slot(-), prio(1)
01/04/24 13:53:59.823208 [0] voice update:  tg(23507), rid(0), freq(851.387500), slot(-), prio(1)
01/04/24 13:54:00.118392 [0] voice update:  tg(23507), rid(0), freq(851.387500), slot(-), prio(1)
01/04/24 13:54:00.486237 [0] voice update:  tg(23507), rid(0), freq(851.387500), slot(-), prio(1)

-v 11
Code:
01/04/24 06:54:51.802646 [clmrn_stamford] set tgid=23507, srcaddr=1359003
01/04/24 06:54:51.802724 [clmrn_stamford] VF ts ph1: tgid: 23507, freq: 852.087500
01/04/24 06:54:51.802762 [0] tsbk(0x00) grp_v_ch_grant: freq: 852.087500 ga: 23507 sa: 1359003
01/04/24 06:54:51.802862 [0] voice update:  tg(23507), rid(1359003), freq(852.087500), slot(-), prio(1)
01/04/24 06:54:51.802899 [0] releasing control channel
01/04/24 06:54:51.802927 [clmrn_stamford] Releasing control channel from receiver[0]
01/04/24 06:54:51.803005 [0] Relative tune: dev_freq(852225000), dev_off(0), dev_frac(0), tune_freq(852087500), tracking(0)
01/04/24 06:54:51.803039 [0] Tuning to frequency 852.087500
01/04/24 06:54:51.803149 [0] frame_assembler_impl::control: cmd(sync_reset), args({"tuner": 0, "cmd": "sync_reset"})
01/04/24 06:54:51.803173 [0] rx_sync::sync_reset:
01/04/24 06:54:51.803282 [0] meta_update: queued[2] msg: {"json_type": "meta_update", "tgid": 23507, "tag": "Fire", "rid": 1359003, "rtag": "888 Op 3"}
01/04/24 06:54:51.803349 [clmrn_stamford] needs control channel receiver
01/04/24 06:54:51.803377 [clmrn_stamford] receiver[0] not idle
01/04/24 06:54:51.803402 [clmrn_stamford] has no idle receivers for control channel monitoring
01/04/24 06:54:51.803482 [0] tsbk(0x09) unhandled: 0x09900f000000000000000000
01/04/24 06:54:51.803566 [0] tsbk(0x0b) unhandled: 0x8b9000000000000001750000
01/04/24 06:54:51.805475 [0] rx_sync::sync_established: protocol P25P1
01/04/24 06:54:51.833856 icemeta::process_q_events: queue size=2
01/04/24 06:54:51.833953 icemeta::run: received message arg1=01/04/24 05:14:21.882579
01/04/24 06:54:51.833994 icemeta::run: processing message
01/04/24 06:54:51.834069 metadata update: "http://127.0.0.1:8000/admin/metadata?mount=/135_fire-all&mode=updinfo&song=Fire"
01/04/24 06:54:51.837730 metadata result: "400"
01/04/24 06:54:51.837799 meta_server::send_metadata(): metadata update error: 400
01/04/24 06:54:51.848386 [0] NAC 0x3a0 TDU15:  LCW: ec=0, pb=0, sf=0, lco=0 : 00 00 04 00 5b d3 00 00 00, gly_errs=0
01/04/24 06:54:51.854139 [0] releasing:  tg(23507), freq(852.087500), slot(-), reason(duid15)
01/04/24 06:54:51.854249 [0] frame_assembler_impl::control: cmd(call_end), args({"tuner": 0, "cmd": "call_end"})
01/04/24 06:54:51.854363 [0] meta_update: queued[2] msg: {"json_type": "meta_update", "tgid": 23507, "tag": "Fire", "rid": null, "rtag": null}
01/04/24 06:54:51.854422 [0] idling receiver
01/04/24 06:54:51.854483 [0] frame_assembler_impl::control: cmd(set_slotid), args({"tuner": 0, "cmd": "set_slotid", "slotid": 4})
01/04/24 06:54:51.854502 [0] rx_sync::set_slot_mask: current(0), new(4)
01/04/24 06:54:51.854599 [clmrn_stamford] needs control channel receiver
01/04/24 06:54:51.854640 [clmrn_stamford] attempt to assign control channel receiver[0]
01/04/24 06:54:51.854669 [clmrn_stamford] Assigning control channel to receiver[0]
01/04/24 06:54:51.854732 [0] frame_assembler_impl::control: cmd(set_slotid), args({"tuner": 0, "cmd": "set_slotid", "slotid": 0})
01/04/24 06:54:51.854748 [0] rx_sync::set_slot_mask: current(4), new(0)
01/04/24 06:54:51.854758 [0] rx_sync::sync_reset:
01/04/24 06:54:51.854775 [0] set control channel=853.337500
01/04/24 06:54:51.854839 [0] Relative tune: dev_freq(852225000), dev_off(0), dev_frac(0), tune_freq(853337500), tracking(0)
01/04/24 06:54:51.854871 [0] Tuning to frequency 853.337500
01/04/24 06:54:51.854941 [0] frame_assembler_impl::control: cmd(sync_reset), args({"tuner": 0, "cmd": "sync_reset"})
01/04/24 06:54:51.854956 [0] rx_sync::sync_reset:
01/04/24 06:54:51.855052 [0] lcw(0x04) unhandled: pb: 0 sf: 0 lcw_data: 0000005bd3000000
01/04/24 06:54:51.869785 [0] rx_sync::sync_established: protocol P25P1
01/04/24 06:54:51.935853 [0] NAC 0x3a0 TSBK: op=02 : 02 00 00 ad 5b d3 00 ad 5b d3 b2 e0
01/04/24 06:54:51.935897 [0] NAC 0x3a0 TSBK: op=3d : 3d 00 13 25 e0 32 09 15 75 62 1b 36
01/04/24 06:54:51.935917 [0] NAC 0x3a0 TSBK: op=30 : b0 00 00 04 2a 06 f9 b1 98 ec 01 0c
01/04/24 06:54:51.937996 icemeta::process_q_events: queue size=2
01/04/24 06:54:51.938068 icemeta::run: received message arg1=01/04/24 05:14:21.882579
01/04/24 06:54:51.938121 icemeta::run: processing message
01/04/24 06:54:51.938218 metadata update: "http://127.0.0.1:8000/admin/metadata?mount=/135_fire-all&mode=updinfo&song=Fire+[888+Op+3]"
01/04/24 06:54:51.942568 metadata result: "400"
01/04/24 06:54:51.942620 meta_server::send_metadata(): metadata update error: 400
01/04/24 06:54:51.945972 [clmrn_stamford] set tgid=23507, srcaddr=0
01/04/24 06:54:51.946056 [clmrn_stamford] VF ts ph1: tgid: 23507, freq: 852.087500
01/04/24 06:54:51.946111 [0] tsbk(0x02) grp_v_ch_grant_up: ch1: 852.087500 ga1: 23507 ch2: 852.087500 ga2: 23507
01/04/24 06:54:51.946249 [0] voice update:  tg(23507), rid(0), freq(852.087500), slot(-), prio(1)
01/04/24 06:54:51.946298 [0] releasing control channel
01/04/24 06:54:51.946332 [clmrn_stamford] Releasing control channel from receiver[0]
01/04/24 06:54:51.946433 [0] Relative tune: dev_freq(852225000), dev_off(0), dev_frac(0), tune_freq(852087500), tracking(0)
01/04/24 06:54:51.946483 [0] Tuning to frequency 852.087500
01/04/24 06:54:51.946625 [0] frame_assembler_impl::control: cmd(sync_reset), args({"tuner": 0, "cmd": "sync_reset"})
01/04/24 06:54:51.946651 [0] rx_sync::sync_reset:
01/04/24 06:54:51.946767 [0] meta_update: queued[2] msg: {"json_type": "meta_update", "tgid": 23507, "tag": "Fire", "rid": 0, "rtag": ""}
01/04/24 06:54:51.946838 [clmrn_stamford] needs control channel receiver
01/04/24 06:54:51.946876 [clmrn_stamford] receiver[0] not idle
01/04/24 06:54:51.946909 [clmrn_stamford] has no idle receivers for control channel monitoring
01/04/24 06:54:51.947027 [0] tsbk(0x3d) iden_up id: 1 toff: 30.000000 spac: 6.250000 freq: 762.006250
01/04/24 06:54:51.989889 [0] rx_sync::sync_established: protocol P25P1
01/04/24 06:54:52.042809 icemeta::process_q_events: queue size=2
01/04/24 06:54:52.042901 icemeta::run: received message arg1=01/04/24 05:14:21.882579
01/04/24 06:54:52.042943 icemeta::run: processing message
01/04/24 06:54:52.043021 metadata update: "http://127.0.0.1:8000/admin/metadata?mount=/135_fire-all&mode=updinfo&song=Fire"
01/04/24 06:54:52.047179 metadata result: "400"
 

boatbod

Member
Joined
Mar 3, 2007
Messages
3,409
Location
Talbot Co, MD
Part (or possibly most) of the the problem is that valid RIDs are coming through and then very quickly being overwritten by RID=0.
Code:
01/04/24 13:51:26.298242 [0] voice update:  tg(23577), rid(1353146), freq(851.662500), slot(-), prio(2)
01/04/24 13:51:26.453552 [0] voice update:  tg(23577), rid(0), freq(851.662500), slot(-), prio(2)

Unfortunately the -v11 log fragment does not contain enough traffic to analyze what's going on with any certainty, but in the one instance of receiving a valid RID and tuning the voice channel the call is immediately torn down by reception of a TDU15 (terminator).
 
Last edited:

ASTRO_Man

Member
Premium Subscriber
Joined
Mar 8, 2010
Messages
267
Thanks for analyzing my logs boatbod, and I am sorry I didn't provide enough data initially. I have better analyzed the stderr.2 log and found a conversation that contained both the TGID and RID in the metadata twice in the same minute, mixed along with other "metadata update" timestamps with just the TGID and not the RID.

The timestamps that contain TGID and RID both are:
06:54:51.938218
06:54:58.994880

I'll paste as much as the logs from the conversation here, and here is a link to Pastebin with the complete conversation logs as it's too large to post here. Again, thank you boatbod for your continued help and support!

Code:
01/04/24 06:54:51.803349 [clmrn_stamford] needs control channel receiver
01/04/24 06:54:51.803377 [clmrn_stamford] receiver[0] not idle
01/04/24 06:54:51.803402 [clmrn_stamford] has no idle receivers for control channel monitoring
01/04/24 06:54:51.803482 [0] tsbk(0x09) unhandled: 0x09900f000000000000000000
01/04/24 06:54:51.803566 [0] tsbk(0x0b) unhandled: 0x8b9000000000000001750000
01/04/24 06:54:51.805475 [0] rx_sync::sync_established: protocol P25P1
01/04/24 06:54:51.833856 icemeta::process_q_events: queue size=2
01/04/24 06:54:51.833953 icemeta::run: received message arg1=01/04/24 05:14:21.882579
01/04/24 06:54:51.833994 icemeta::run: processing message
01/04/24 06:54:51.834069 metadata update: "http://127.0.0.1:8000/admin/metadata?mount=/135_fire-all&mode=updinfo&song=Fire"
01/04/24 06:54:51.837730 metadata result: "400"
01/04/24 06:54:51.837799 meta_server::send_metadata(): metadata update error: 400
01/04/24 06:54:51.848386 [0] NAC 0x3a0 TDU15:  LCW: ec=0, pb=0, sf=0, lco=0 : 00 00 04 00 5b d3 00 00 00, gly_errs=0
01/04/24 06:54:51.854139 [0] releasing:  tg(23507), freq(852.087500), slot(-), reason(duid15)
01/04/24 06:54:51.854249 [0] frame_assembler_impl::control: cmd(call_end), args({"tuner": 0, "cmd": "call_end"})
01/04/24 06:54:51.854363 [0] meta_update: queued[2] msg: {"json_type": "meta_update", "tgid": 23507, "tag": "Fire", "rid": null, "rtag": null}
01/04/24 06:54:51.854422 [0] idling receiver
01/04/24 06:54:51.854483 [0] frame_assembler_impl::control: cmd(set_slotid), args({"tuner": 0, "cmd": "set_slotid", "slotid": 4})
01/04/24 06:54:51.854502 [0] rx_sync::set_slot_mask: current(0), new(4)
01/04/24 06:54:51.854599 [clmrn_stamford] needs control channel receiver
01/04/24 06:54:51.854640 [clmrn_stamford] attempt to assign control channel receiver[0]
01/04/24 06:54:51.854669 [clmrn_stamford] Assigning control channel to receiver[0]
01/04/24 06:54:51.854732 [0] frame_assembler_impl::control: cmd(set_slotid), args({"tuner": 0, "cmd": "set_slotid", "slotid": 0})
01/04/24 06:54:51.854748 [0] rx_sync::set_slot_mask: current(4), new(0)
01/04/24 06:54:51.854758 [0] rx_sync::sync_reset:
01/04/24 06:54:51.854775 [0] set control channel=853.337500
01/04/24 06:54:51.854839 [0] Relative tune: dev_freq(852225000), dev_off(0), dev_frac(0), tune_freq(853337500), tracking(0)
01/04/24 06:54:51.854871 [0] Tuning to frequency 853.337500
01/04/24 06:54:51.854941 [0] frame_assembler_impl::control: cmd(sync_reset), args({"tuner": 0, "cmd": "sync_reset"})
01/04/24 06:54:51.854956 [0] rx_sync::sync_reset:
01/04/24 06:54:51.855052 [0] lcw(0x04) unhandled: pb: 0 sf: 0 lcw_data: 0000005bd3000000
01/04/24 06:54:51.869785 [0] rx_sync::sync_established: protocol P25P1
01/04/24 06:54:51.935853 [0] NAC 0x3a0 TSBK: op=02 : 02 00 00 ad 5b d3 00 ad 5b d3 b2 e0
01/04/24 06:54:51.935897 [0] NAC 0x3a0 TSBK: op=3d : 3d 00 13 25 e0 32 09 15 75 62 1b 36
01/04/24 06:54:51.935917 [0] NAC 0x3a0 TSBK: op=30 : b0 00 00 04 2a 06 f9 b1 98 ec 01 0c
01/04/24 06:54:51.937996 icemeta::process_q_events: queue size=2
01/04/24 06:54:51.938068 icemeta::run: received message arg1=01/04/24 05:14:21.882579
01/04/24 06:54:51.938121 icemeta::run: processing message
01/04/24 06:54:51.938218 metadata update: "http://127.0.0.1:8000/admin/metadata?mount=/135_fire-all&mode=updinfo&song=Fire+[888+Op+3]"
01/04/24 06:54:51.942568 metadata result: "400"
01/04/24 06:54:51.942620 meta_server::send_metadata(): metadata update error: 400
01/04/24 06:54:51.945972 [clmrn_stamford] set tgid=23507, srcaddr=0
01/04/24 06:54:51.946056 [clmrn_stamford] VF ts ph1: tgid: 23507, freq: 852.087500
01/04/24 06:54:51.946111 [0] tsbk(0x02) grp_v_ch_grant_up: ch1: 852.087500 ga1: 23507 ch2: 852.087500 ga2: 23507
01/04/24 06:54:51.946249 [0] voice update:  tg(23507), rid(0), freq(852.087500), slot(-), prio(1)
01/04/24 06:54:51.946298 [0] releasing control channel
01/04/24 06:54:51.946332 [clmrn_stamford] Releasing control channel from receiver[0]
01/04/24 06:54:51.946433 [0] Relative tune: dev_freq(852225000), dev_off(0), dev_frac(0), tune_freq(852087500), tracking(0)
01/04/24 06:54:51.946483 [0] Tuning to frequency 852.087500
01/04/24 06:54:51.946625 [0] frame_assembler_impl::control: cmd(sync_reset), args({"tuner": 0, "cmd": "sync_reset"})
01/04/24 06:54:51.946651 [0] rx_sync::sync_reset:
01/04/24 06:54:51.946767 [0] meta_update: queued[2] msg: {"json_type": "meta_update", "tgid": 23507, "tag": "Fire", "rid": 0, "rtag": ""}
01/04/24 06:54:51.946838 [clmrn_stamford] needs control channel receiver
01/04/24 06:54:51.946876 [clmrn_stamford] receiver[0] not idle
01/04/24 06:54:51.946909 [clmrn_stamford] has no idle receivers for control channel monitoring
01/04/24 06:54:51.947027 [0] tsbk(0x3d) iden_up id: 1 toff: 30.000000 spac: 6.250000 freq: 762.006250
01/04/24 06:54:51.989889 [0] rx_sync::sync_established: protocol P25P1
01/04/24 06:54:52.042809 icemeta::process_q_events: queue size=2
01/04/24 06:54:52.042901 icemeta::run: received message arg1=01/04/24 05:14:21.882579
01/04/24 06:54:52.042943 icemeta::run: processing message
01/04/24 06:54:52.043021 metadata update: "http://127.0.0.1:8000/admin/metadata?mount=/135_fire-all&mode=updinfo&song=Fire"
01/04/24 06:54:52.047179 metadata result: "400"
01/04/24 06:54:52.047227 meta_server::send_metadata(): metadata update error: 400
01/04/24 06:54:52.066547 [0] NAC 0x3a0 HDU:  ESS: tgid=23507, mfid=0, algid=80, keyid=0, mi=00 00 00 00 00 00 00 00 00, gly_errs=0, rs_errs=0
01/04/24 06:54:52.147430 icemeta::process_q_events: queue size=1
01/04/24 06:54:52.147579 icemeta::run: received message arg1=01/04/24 05:14:21.882579
01/04/24 06:54:52.147752 icemeta::run: processing message
01/04/24 06:54:52.147885 metadata update: "http://127.0.0.1:8000/admin/metadata?mount=/135_fire-all&mode=updinfo&song=Fire"
01/04/24 06:54:52.152206 metadata result: "400"
01/04/24 06:54:52.152278 meta_server::send_metadata(): metadata update error: 400
01/04/24 06:54:52.241756 [0] NAC 0x3a0 LDU1: LCW: ec=0, pb=0, sf=0, lco=0 : 00 00 04 00 5b d3 00 00 00
01/04/24 06:54:52.241835 [0] IMBE b0 59 f2 f7 9e bc 00 09 4b 00 89 errs 0
01/04/24 06:54:52.243227 [0] IMBE 18 66 63 53 6e 6e 07 37 46 6d 5a errs 0
01/04/24 06:54:52.244434 [0] IMBE 18 65 a4 44 e8 ae 07 e2 a4 e5 2b errs 0
01/04/24 06:54:52.245608 [0] IMBE 18 67 a0 60 92 4d 07 88 7d 7c b2 errs 0
01/04/24 06:54:52.246726 [0] IMBE 18 72 ca 1a 6d 46 06 5e 70 83 73 errs 0
01/04/24 06:54:52.247473 [0] IMBE 18 73 09 09 b5 25 07 32 53 04 e2 errs 0
01/04/24 06:54:52.248289 [0] IMBE 38 ff 79 e1 bd 30 80 7e f8 e2 83 errs 0
01/04/24 06:54:52.248997 [0] IMBE 38 f6 ea 64 89 63 e0 9c e2 7b 92 errs 0
01/04/24 06:54:52.249543 [0] IMBE 34 f0 ec 86 8c 7b 81 79 bd 67 85 errs 0
01/04/24 06:54:52.251179 [0] lcw(0x04) unhandled: pb: 0 sf: 0 lcw_data: 0000005bd3000000
01/04/24 06:54:52.251275 [0] process_qmsg: P25 info: b'{"encrypted": 0, "algid": 128, "keyid": 0}'
01/04/24 06:54:52.251406 [0] process_qmsg: P25 info: b'{"encrypted": 0, "algid": 128, "keyid": 0}'
01/04/24 06:54:52.251556 [0] process_qmsg: P25 info: b'{"encrypted": 0, "algid": 128, "keyid": 0}'
01/04/24 06:54:52.251696 [0] process_qmsg: P25 info: b'{"encrypted": 0, "algid": 128, "keyid": 0}'
01/04/24 06:54:52.251839 [0] process_qmsg: P25 info: b'{"encrypted": 0, "algid": 128, "keyid": 0}'
01/04/24 06:54:52.251981 [0] process_qmsg: P25 info: b'{"encrypted": 0, "algid": 128, "keyid": 0}'
01/04/24 06:54:52.252123 [0] process_qmsg: P25 info: b'{"encrypted": 0, "algid": 128, "keyid": 0}'
01/04/24 06:54:52.252270 [0] process_qmsg: P25 info: b'{"encrypted": 0, "algid": 128, "keyid": 0}'
01/04/24 06:54:52.252403 [0] process_qmsg: P25 info: b'{"encrypted": 0, "algid": 128, "keyid": 0}'
01/04/24 06:54:52.426890 [0] NAC 0x3a0 LDU2: ESS: algid=80, keyid=0, mi=00 00 00 00 00 00 00 00 00, rs_errs=0

...

01/04/24 06:54:58.993468 [clmrn_stamford] VF ts ph1: tgid: 23507, freq: 851.662500
01/04/24 06:54:58.993500 [0] tsbk(0x00) grp_v_ch_grant: freq: 851.662500 ga: 23507 sa: 10443
01/04/24 06:54:58.993621 [0] voice update:  tg(23507), rid(10443), freq(851.662500), slot(-), prio(1)
01/04/24 06:54:58.993658 [0] releasing control channel
01/04/24 06:54:58.993686 [clmrn_stamford] Releasing control channel from receiver[0]
01/04/24 06:54:58.993758 [0] Relative tune: dev_freq(852225000), dev_off(0), dev_frac(0), tune_freq(851662500), tracking(0)
01/04/24 06:54:58.993793 [0] Tuning to frequency 851.662500
01/04/24 06:54:58.993894 [0] frame_assembler_impl::control: cmd(sync_reset), args({"tuner": 0, "cmd": "sync_reset"})
01/04/24 06:54:58.993936 [0] rx_sync::sync_reset:
01/04/24 06:54:58.994043 [0] meta_update: queued[1] msg: {"json_type": "meta_update", "tgid": 23507, "tag": "Fire", "rid": 10443, "rtag": "Medic 1 B"}
01/04/24 06:54:58.994111 [clmrn_stamford] needs control channel receiver
01/04/24 06:54:58.994140 [clmrn_stamford] receiver[0] not idle
01/04/24 06:54:58.994166 [clmrn_stamford] has no idle receivers for control channel monitoring
01/04/24 06:54:58.994285 [0] tsbk(0x39) sccb: rfid: 3 stid: 2 ch1: 14d(853.087500) ch2: 11d(852.787500)
01/04/24 06:54:58.994685 icemeta::process_q_events: queue size=1
01/04/24 06:54:58.994744 icemeta::run: received message arg1=01/04/24 05:14:21.882579
01/04/24 06:54:58.994792 icemeta::run: processing message
01/04/24 06:54:58.994880 metadata update: "http://127.0.0.1:8000/admin/metadata?mount=/135_fire-all&mode=updinfo&song=Fire+[Medic+1+B]"
01/04/24 06:54:58.999056 metadata result: "400"
01/04/24 06:54:58.999104 meta_server::send_metadata(): metadata update error: 400
01/04/24 06:54:59.024300 [0] rx_sync::sync_established: protocol P25P1
01/04/24 06:54:59.067517 [0] NAC 0x3a0 TDU15:  LCW: ec=0, pb=0, sf=0, lco=0 : 00 00 04 00 5b d3 00 00 00, gly_errs=0
01/04/24 06:54:59.075120 [0] releasing:  tg(23507), freq(851.662500), slot(-), reason(duid15)
01/04/24 06:54:59.075261 [0] frame_assembler_impl::control: cmd(call_end), args({"tuner": 0, "cmd": "call_end"})
01/04/24 06:54:59.075393 [0] meta_update: queued[1] msg: {"json_type": "meta_update", "tgid": 23507, "tag": "Fire", "rid": null, "rtag": null}
01/04/24 06:54:59.075465 [0] idling receiver
01/04/24 06:54:59.075527 [0] frame_assembler_impl::control: cmd(set_slotid), args({"tuner": 0, "cmd": "set_slotid", "slotid": 4})
01/04/24 06:54:59.075545 [0] rx_sync::set_slot_mask: current(0), new(4)
01/04/24 06:54:59.075625 [clmrn_stamford] needs control channel receiver
01/04/24 06:54:59.075658 [clmrn_stamford] attempt to assign control channel receiver[0]
01/04/24 06:54:59.075684 [clmrn_stamford] Assigning control channel to receiver[0]
01/04/24 06:54:59.075744 [0] frame_assembler_impl::control: cmd(set_slotid), args({"tuner": 0, "cmd": "set_slotid", "slotid": 0})
01/04/24 06:54:59.075760 [0] rx_sync::set_slot_mask: current(4), new(0)
01/04/24 06:54:59.075771 [0] rx_sync::sync_reset:
01/04/24 06:54:59.075791 [0] set control channel=853.337500
01/04/24 06:54:59.075867 [0] Relative tune: dev_freq(852225000), dev_off(0), dev_frac(0), tune_freq(853337500), tracking(0)
01/04/24 06:54:59.075902 [0] Tuning to frequency 853.337500
01/04/24 06:54:59.075980 [0] frame_assembler_impl::control: cmd(sync_reset), args({"tuner": 0, "cmd": "sync_reset"})
01/04/24 06:54:59.075996 [0] rx_sync::sync_reset:
01/04/24 06:54:59.076096 [0] lcw(0x04) unhandled: pb: 0 sf: 0 lcw_data: 0000005bd3000000
01/04/24 06:54:59.099307 icemeta::process_q_events: queue size=1
01/04/24 06:54:59.099373 icemeta::run: received message arg1=01/04/24 05:14:21.882579
01/04/24 06:54:59.099411 icemeta::run: processing message
01/04/24 06:54:59.099480 metadata update: "http://127.0.0.1:8000/admin/metadata?mount=/135_fire-all&mode=updinfo&song=Fire"
01/04/24 06:54:59.103693 metadata result: "400"
01/04/24 06:54:59.103744 meta_server::send_metadata(): metadata update error: 400
 

boatbod

Member
Joined
Mar 3, 2007
Messages
3,409
Location
Talbot Co, MD
What I'm looking for is a "voice update:" log message with non-zero RID and then what gets received immediately after tuning to the voice channel. In your most recent log we have this sequence, which is very similar to what I saw in the previous log fragment:
Code:
01/04/24 06:54:58.993621 [0] voice update:  tg(23507), rid(10443), freq(851.662500), slot(-), prio(1)
...
01/04/24 06:54:59.024300 [0] rx_sync::sync_established: protocol P25P1
01/04/24 06:54:59.067517 [0] NAC 0x3a0 TDU15:  LCW: ec=0, pb=0, sf=0, lco=0 : 00 00 04 00 5b d3 00 00 00, gly_errs=0
01/04/24 06:54:59.075120 [0] releasing:  tg(23507), freq(851.662500), slot(-), reason(duid15)
 
Top