Debug log

Description of some of the messages found in the debug log.

Most of the generated debug messages relates to the structure of the software of the AMC, the SDL and C-code itself. For example there are 74 SDL state machines with approx 3000 states able to send more than 2000 different signals to each other. If any state machine send signal X to another state machine which has not a handle for signal X in its current state an “UNEXP_SIG” or "UNEXP_SWITCH" message is generated telling the name of the signal, the sender and the receive state. This is handy when debugging the code but no easy to describe in beforehand since the system itself gives several million possibilities and ideally should not occur.

The log event might start with a letter:

• W = Warning
• E = Error
• D = Disaster (causes reset)

Followed by two number, e.g. (1.65). This is the source for the log event; 1= node 1 65 = Device number (65 = main AlphaCom module).

Directory Table

W(1.65) ERR_NVRAM, no:26  "CTNS_GPDH2" P1: 0, P2: 29, P3: 863

An element in the directory tables internal hash fast lookup table has a wrong value.
(The directory table sorting system (TNS) will be triggered for rebuilding)

W(1.65) TNS_VERIFY, no:34  "CTNS_V_NOW" P1: 0, P2: 0, P3: 0 

The directory table sorting system is triggered for verification/rebuild (Verify Now) .

W(1.65) TNS_VERIFY, no:35  "CTNS_REGEN" P1: 0, P2: 0, P3: 0

The directory table sorting system is regenerated.

W(1.65) ERR_NVRAM, no:5564  "CTNS_NUM_1" P1: 25, P2: 65535, P3: 5

There are some corrupted elements in the directory table.

P1: = First error element, referes to the internal tns structure. (nvram .ex_tns.tab[9637])

P2: = Error type of first fault, 65535 = Directory number without number (empty number).

P3: = Number of faults found. <nr>

Data Protocol

(1.65) ERROR, BUFFER_TOO_SMALL, at 2014-01-15 11:22:33, no:31026 SIS#1 sent ABSENCE_STATUS to DP#1 state DP/Operating (1) Desc:"DpAddNumb" P1: 2, P2: 199, P3: 0

The "Buffer to small" message is stating that there is an attempt to create an AlphaNet message that is longer than 200 bytes when "Absence_Status" is generated.

E(1.65) UNEXP_SWITCH, no:27  "DplcSndMsg" P1: 7, P2: 1, P3: 0

The ACDP link is not operational thus no message could be sent.

P1: = Link number (ACDP link)

P2: = Link address (Device number)

INFO_DPMR_NO_ROUTE, no:1279  CSI#1 sent READY to CSI#1 state CSI/ReadingCommands (3)"" P1: 1, P2: 62, P3: 0 Packet to node 1 device 62 dropped, no routing information

The routing to node 1 device 62 is not available.
(Typically after reset before the links are up, or due to no configuration of the route to node/device)

(1.65) ILLEGAL_PAR, no:56440  DP#11 sent DP_ANALYSE_MSG to DP#1 state DP/Operating (1)"DpTypNoAdd" P1: 160, P2: 1, P3: 13 
(1.65) ILLEGAL_PAR, no:56441  DP#11 sent DP_ANALYSE_MSG to DP#1 state DP/Operating (1)"DpIllAdr" P1: 137, P2: 65, P3: 6 

Illegal Message type or message parameter fault. Two error messages are reported to include 6 parameters with information.

Parameters:

"DpTypNoAdd"

P1:160 = Message type 0xA0 DIP_FWD

P2:1 = Parameter number with error (Not relevant in this example)

P3:13 = Value of the parameter (Not relevant in this example)

"DpIllAdr"

P1:137 = Message reference of the header of message.

P2:65 = Device ID of the sender

P3:6 = Node number of the sender

Reason for this example message:
DIP_FWD is not defined in older nodes.
This DIP_FWD message error can be produced in AlphaNet audio setup when nodes have different software versions. For later AlphaSys version the software version of other nodes will be checked before sending the "DIP_FWD" message to avoid error messages from older nodes.

(1.65) ILLEGAL_PAR, no:701  DP#3 sent DP_ANALYSE_MSG to DP#1 state DP/Operating (1)"DpMsgType" P1: 6284, P2: 0, P3: 0 )

This message is generated when the AlphaNet type number is not known.

Parameters:

"DpMsgType"

P1:6284 = Message type. AlphaNet message "6284" is not defined in the AlphaNet protocol.

P2:0 = Not used

P3:0 = Not used

Special case: Illegal Parameter/Illegal magic char. Example: A wrong magic char like $CANM L143 L85 LM17 U140 (correct is NM17)

The internal parser converting from simple link format to binary format sees the wrong placed "M" as start of a new AlphaNet message since "M" is used for Message Type. For some reason the preceding characters is converted to message type 6284.

D(1.65) ERR_ASSERT, no:5383  "DplcSnMsg1" P1: -2, P2: 1, P3: 0

Trace Event from Interface AMC_CMD_SERVER: Restarting AMC on command

This message means that message queue for ACDP link 1 is filled up. This assert (caused by a disaster) leads to a reset of amcd.

Conversation

E(1.65) UNEXP_SIG, no:5285  TF#1 sent SW_ERR_TIMER to SCM#125 state SCM/PendingDiscon (19)"SCMSwErr" P1: 0, P2: 5, P3: 0

A conversation is disconnected, the call process awaits acknowledge for the cancellation from the subscriber processes.
Acknowledge is not received within timeout, a sw error timer will clean up the conversation.

P1: Station 2 of the conversation

P2: Station 1 of the conversation

When station = 0 it has acknowledge. Thus in this case station 5 has not sent acknowledge.

W(1.65) UNEXP_SIG, no:4413  CONN#2 sent ST_M_PRES to SCM#189 state SCM/DuplSimplMPres1 (3)"SCMdsmp1" P1: 0, P2: 0, P3: 0

Conversation
M Pres received from a station that already have the status of "M-PRES".
(M from $DP or event handler?)

E(1.65) UNEXP_SIG, no:6222  TF#1 sent MKEY_TIMER to SCM#172 state SCM/IPIPOpenSimplMRel (9)"SCM200" P1: 0, P2: 0, P3: 0

An conversation between two IP stations in M-key controlled simplex. A timing situation occur where both stations uses "M" is not handled correctly. Fixed for 11.2.3.4.

E(1.65) UNEXP_SIG, no:5519  SCM#213 sent ST_M_PRES to SCM#213 state SCM/NotInUse (1)"SCM200" P1: 0, P2: 0, P3: 0

An unused conversation channel receives a M PRES signal. This could occur if an remote node is out of sync with active AlphaNet connection, reset of own node...

E(110.65) ERR_IN_TST, no:23  TH#605 sent TONE_END_RCTRL to CONN#3 state SDCONN/WaitB_Timeout_TH (8)"TstErrFun1" P1: 3004, P2: 1131282432, P3: 0 

P1: module * 1000 + code

• module = 3, Message sending
• code = 4, Undefined process

Internal process signaling failed. An acknowledge for turning off tone in a conversation was received after the conversation ended.

W(1.65) APR_INVAL_NEXT_NODE, no:5993  SCM#80 sent PROCEED to SCM#80 state SDAPR/AudioPathStartWaitRoute (2)"Route0" P1: 2, P2: 0, P3: 1 Invalid next audio node from own node 1 to destination node 2

No available data or audio route found to next node. Could be node down.

E(1.65) UNEXP_SIG, no:5519  DP#1 sent CHECK_AUDIO_PATH to SCM#213 SCM/NotInUse (1)"SCM200" P1: 0, P2: 0, P3: 0

Remote node (AlphaCom, SIP, M100, RMD++) believes an AlphaNet connection is up and send a "Alpha net Check" to verify that the connection is still up, but this node has not this connection active.
This will happen if one node in AlphaNet is reset while active conversations between nodes. The remote node will disconnect the connection when no reply received on the "CHECK_AUDIO_PATH" message is received withing 70 seconds.

Subscriber key signaling

E(1.65) UNEXP_SIG, no:1281  SBS#30 sent M_PRES_SBS to SBS#30 state SBS/IdleOnHook (14)"SBS010" P1: 0, P2: 0, P3: 0

Relates to physical station 30.
The signal M_PRES_SBS is used during active states of a subscriber. (Active in features like a call)
Since the station now is "IdleOnHook" probably the station just came back from an active state and received this signal delayed.
Maybe event handler or $DP signaled M pres?

E(1.65) UNEXP_SIG, no:6 TO_IF#1 sent KEY_PRES to SBS#30 state SBS/NoSLI 
(1)"SBS010" P1: 0, P2: 0, P3: 0 (1)"SBS010" P1: 0, P2: 0, P3: 0

E(1.65) UNEXP_SIG, no:87  TO_IF#1 sent KEY_REL to SBS#30 state SBS/NoSLI 
(1)"SBS010" P1: 0, P2: 0, P3: 0 (1)"SBS010" P1: 0, P2: 0, P3: 0 

Relates to physical station 30.
The station is in state "No subscriber line interface", this means not connected/registered or not found jet (ASLT scanning after reset.)
The station receives a KEY PRES/KEY RELEASE signal, this should not be possible unless the signal comes from event handler or $DP signaled key pres.

E(1.65) UNEXP_SIG, no:5714  UNDEFINED PROCESS#0 sent KEY_PRES to SBS#30 state SBS/NoSLI (1)"SBS010" P1: 0, P2: 0, P3: 0

E(1.65) UNEXP_SIG, no:5716  UNDEFINED PROCESS#0 sent KEY_REL to SBS#30 state SBS/NoSLI (1)"SBS010" P1: 0, P2: 0, P3: 0

Same as above but probably early in restart of AlphaCom thus not all processes have been initiated jet.

E(1.65) UNEXP_SIG, no:5512  DP#1 sent C_PRES to SBS#37 state SBS/NoSLI (1)"SBS010" P1: 0, P2: 0, P3: 0 

E(1.65) UNEXP_SIG, no:5513  DP#1 sent C_REL to SBS#37 state SBS/NoSLI (1)"SBS010" P1: 0, P2: 0, P3: 0

Relates to physical station 37.
C PRES / RELEASE signaling are coming from data protocol to a station not connected/registred.

E(1.65) UNEXP_SIG, no:7  DP#1 sent M_PRES to SBS#30 state SBS/NoSLI (1)"SBS010" P1: 0, P2: 0, P3: 0

Relates to physical station 30.
The station is in state "No subscriber line interface", this means not connected/registered or not found jet after reset.
The station receives a M_PRES signal from date protocol. I.e. from Event Handler or ACDP.

E(1.65) UNEXP_SWITCH, no:4817  TH#40 sent TONE_END_RCTRL to SBS#40 state SDACTIV/ADC_FeatToneStop (67)"SbsSbsFeat" P1: 22, P2: 0, P3: 0

Physical station 40.
Feature activated (during conversation) the feature dialed was not allowed in this situation.

P1: Feature number. (22 = Microphone Mute)

Other Subscriber signaling

E(1.65) UNEXP_SIG, no:5916  SBS#30 sent SBS_DISCON to SBS#30 state SBS/StationActive (56)"SBS010" P1: 0, P2: 0, P3: 0

Relates to station 30.
The station has just left active state and a delayed "disconnect" signal only used in the active state is received. This signal should just be ignored. Fixed for 11.2.3.4

E(1.65) UNEXP_SIG, no:1 TO_IF#1 sent ON_HOOK to SBS#1 state SBS/IdleOnHook 
(1)"SBS010" P1: 0, P2: 0, P3: 0 (1)"SBS010" P1: 0, P2: 0, P3: 0

Station 1 who already is in state "idle on-hook" receives a new ON_HOOK signal from the hardware I/F.
Could happen if HOOK signaling is both sent from $DP messages (event handler) and from the station itself.

License

W(1.65) TABLE, no:57  "CipherErr" P1: 0, P2: 0, P3: 0

If no legal license key is present in the exchange
Corrupted license string.
System without license string
Could be wrong license MAC address.
Issues with reading own MAC address?

D(1.65) TABLE, no:2420  "LicTimeout" P1: 0, P2: 0, P3: 0 )

License free periode is over. Install a legal license key or set exchange to factory defaults.

RCI - RCO

There where made RCI/RCO related fixes 11.2.3.2.

• Multi Drop Master protocol
• RCO timers where made individual.
• New flag for automatically sync of RCI state ON/OFF when RIO/MIO reports states out of the AMC expected order. .ex_profile.flags.RCI_sync = 0

RCI

W(1.65) UNEXP_SIG, no:36262  DP#1 sent SCAN_RCI_ACK to RCI#51 state RCI/WaitResp (8)"sRCI010" P1: 0, P2: 0, P3: 0

Relate to logical RCI 51. The input device (RIO/MIO) is sending $SCAN_RCI_ACK in a state where $RCI_IS_ON or $RCI_IS_OFF is expected.
Last signal received before this state was $SCAN_RCI_ACK, thus it looks like double signaling.

W(1.65) UNEXP_SIG, no:257  DP#1 sent SCAN_RCI_ACK to RCI#71 state RCI/WaitRespAlarm (14)"sRCI010" P1: 0, P2: 0, P3: 0

Relates to RCI 71.
The RCI is active, expected signal is RCI_ON or RCI_OFF (dependent on the polarity setting).
Instead SCAN_RCI_ACK is received.

W(1.65) UNEXP_SWITCH, no:4999  DP#1 sent RCI_IS_OFF to RCI#71 state RCI/WaitRespAlarm (14)"RciOfPolar" P1: 0, P2: 0, P3: 0

Relates to RCI 71
The RCI is currently OFF, only new legal state is RCI_IS_ON. The RIO/MIO is reporting state RCI_IS_OFF. (With the flag RCI_sync = 1 this will be resolved)

W(1.65) UNEXP_SIG, no:5566  DP#1 sent RCI_IS_OFF to RCI#72 state RCI/Pending (3)"sRCI010" P1: 0, P2: 0, P3: 0 
W(1.65) UNEXP_SIG, no:5567  DP#1 sent RCI_IS_ON to RCI#72 state RCI/Pending (3)"sRCI010" P1: 0, P2: 0, P3: 0

Relates to RCI 72.
The RCI is in state Pending, it means the MIO/RIO device has not been reported up jet. Since the device is not available no state changes are accepted. (RCI ON/OFF is reported from the device)

RCO

W(1.65) UNEXP_SWITCH, no:65294  DP#1 sent CLEAR_RCO_ACK to RCO#1 state RCO/Running (1)"RcoUnexp" P1: 7, P2: 0, P3: 0.

P1: RCO number 7

Unexpected CLEAR_RCO_ACK from RIO/MIO, (no pending ACK for this RCO). Could it be resending of CLEAR_RCO_ACK?

W(1.65) UNEXP_SWITCH, no:5284  DP#1 sent CLEAR_RCO_ACK to RCO#1 state RCO/Running (1)"RcoPolarit" P1: 22, P2: 0, P3: 0 

P1: RCO number 22

There is a pending acknowledge for this RCO but it should be SET_RCO_ACK not CLEAR_RCO_ACK.

W(1.65) UNEXP_SWITCH, no:10429  DP#1 sent SET_RCO_ACK to RCO#1 state RCO/Running (1)"RcoPolarit" P1: 8, P2: 0, P3: 0

Relates to RCO 7 (P1)
unexpected SET_RCO_ACK from RIO/MIO, (no pending ACK for this RCO). Could it be resending of SET_RCO_ACK?

W(1.65) UNEXP_SWITCH, no:59970  DP#1 sent SET_RCO_ACK to RCO#1 state RCO/Running (1)"RcoNoMatch" P1: 137, P2: 2, P3: 2 
W(1.65) UNEXP_SWITCH, no:59971  DP#1 sent CLEAR_RCO_ACK to RCO#1 state RCO/Running (1)"RcoNoMatch" P1: 137, P2: 2, P3: 2

The RCO is not found in the configuration

P1 = Logical RCO number

P2 = Device number

P3 = Pin number (on the device)

Group Call (Voice paging)

E(8.65) UNEXP_SIG, no:2375  VP#1 sent TRANSPARENT to SBS#225 state SDACTIV/ExitSbsDisc (113)"SSBS100" P1: 0, P2: 0, P3: 0

This message is related to group call (VP = Voice Paging). The station seems to disconnect on a very inconvenient time. Maybe the group call is blocked or hanging?!

E(1.65) UNEXP_SIG, no:331  SBS#20 sent DIGIT to VP#1 state VP/HelpFinished (93)"VP010" P1: 20, P2: 2, P3: 0 )

This message is related to group call (VP = Voice Paging). Occurs when station is initiating a group call and press digits during group call. This message is harmless and can be ignored.

Conference

E(1.65) ILLEGAL_PAR, no:39413  SPF#30 sent ST_TALK_STOP to CNF#5 state CNF/Operating (1)"CnfTalkSto" P1: 30, P2: 0, P3: 0 

Physical station 30 was asked to stop talking in conference 5, but no one was talking in the conference.

P1 = New Talker To stop

P2 = Current talker

E(1.65) UNEXP_SIG, no:39414  SPF#30 sent DP_TALK_END_RCTRL to SBS#30 state SBS/IdleOnHook (14)"SBS010" P1: 0, P2: 0, P3: 0

This is a result of the "CnfTalkSto" error message.
Conference 5 was replying to the "stop talking message" but subscriber 30 was not talking, "IdleOnHook".

E(1.65) UNEXP_SIG, no:41065  SPF#37 sent DP_TALK_SUCCESS to SBS#37 state SBS/GoActiveKeyPres (52)"SBS010" P1: 0, P2: 0, P3: 0 

Station 37 entered talk mode in a conference at the same moment as a key pres was activated on the station.
This resulted in the acknowledge message "DP_TALK_SUCCESS" from the conference was received in a transit state for activating the station because of key pres.

E(1.65) UNEXP_SIG, no:41068  SPF#37 sent CONFERENCE_MODE to SBS#37 state SBS/ConfGoTalk (76)"SBS010" P1: 0, P2: 0, P3: 0 

Station 37 is entering talk mode in a conference and at the same time receives a signal for entering conference mode.
The subscriber and the conference seams to be out of sync, or $DP conference messages are interfering the internal state changes of the station

E(1.65) UNEXP_SIG, no:5278  SPF#40 sent CONFERENCE_MODE to SBS#40 state SBS/NoSLI (1)"SBS010" P1: 0, P2: 0, P3: 0

Station 40 is asked to join a conference, but the station is not registered or connected.

E(1.65) UNEXP_SIG, no:21354  SPF#30 sent NORMAL_MODE to SBS#30 state SBS/IdleOnHook (14)"SBS010" P1: 0, P2: 0, P3: 0

Physical station 30 is asked to leave conference mode and return to idle, but the station is already in idle.
(Conference and station mismatch in state, $DP messages?)

E(1.65) UNEXP_SIG, no:4848  SPF#37 sent NORMAL_MODE to SBS#37 state SBS/ConfTalkBusy (79)"SBS010" P1: 0, P2: 0, P3: 0

Related to physical station 37.
Station tries to talk in to a conference (M-pres) but the station is rejected from talk because an other talker is active. In this state the station is asked to disconnect from the conference ("NORMAL MODE"). (This message could occur if an Alarm message or program with volume override is started, due to the more "brutal" way of forcing the station.)

E(8.65) UNEXP_SIG, no:3038  TO_IF#1 sent RTP_RX_ACK to CP#20 state CP/FadingNoSource (2)"sCP010" P1: 0, P2: 0, P3: 0

The internal message RTP_RX_ACK is used to acknowledge that an IP audio source has started sending RTP audio to AlphaCom. The “UNEXP_SIG” debug log entry is because the SX-Conference is in the state “FadingNoSource”, meaning there are no source audio connected to the conference when the RTP_RX_ACK was received (No speaking of the conference, thus acknowledge on received audio is unexpected). The fault message could theoretically be generated if doing a fast transition from start feeding audio to stop feeding (Short M press).

IP Station

W(1.65) TABLE, no:5811  "NoPong" P1: 121, P2: 0, P3: 0

P1: IP station physical number.

The IP station application has not replied to a PING messages. The IP socket to the station is terminated.

W(1.65) TABLE, no:197  "SockFail" P1: 32, P2: 0, P3: 0

P1: IP station physical number.

IP station socket for data communication is closed but the IP station state in AlphaCom is still "UP".
(Checked approx every 5 minute, and station reported down)

E(1.65) UNEXP_SIG, no:5331  TF#1 sent IP_ST_TIMER to IP_ST#30 state IP_ST/connected (1)"NO_RTP" P1: 0, P2: 0, P3: 0

IP station physical number 30 should send RTP audio to AMCd but nothing is received.

E(8.65) UNEXP_SIG, no:2384  TO_IF#1 sent RTP_RX_ACK to CP#23 state CP/PrepareShutMic (61)"sCP010" P1: 0, P2: 0, P3: 0 )

The message is a response for incoming RTP audio from IP-Station to AlphaCom which is a little delayed or out of sync, and is not expected or necessary in this condition. The message RTP_RX_ACK could be related to group call or conference. The conference is in a condition where "speaker" have stopped speaking and is waiting some ms before microphone is closed (PrepareShutMic). During this time AlphaCom is receiving RTP Audio which is not expected. But that the signal is out of sync might be because of something else which hangs....

UNEXP_SWITCH, no:2403 IP_ST#2 sent PCMC_SEEK to ARA#1 state ARA/Idle (1) Desc:"PR_ST" P1: 2, P2: 21, P3: 0

P1: IP station physical number

The "PR_ST" message means that the station is allocated for the backplane and is not allowed to allocate once more. Check if this station is an IP-Station and configured to a physical position where an aslt card is installed! Configure IP-Stations only to a physical position where is not a aslt card installed.

Event Handler

W(1.65) UNEXP_SIG, no:3237  CSI#1 sent CSI_ERROR to EVH#1 state EVH/Idle (1)"sEVH020" P1: 228, P2: 0, P3: 0

P1 Character position of the fault

There is a fault in an Event Script. The system log contains more related information:

syntax error in Event (15)EvntTri.6a on  owner sta 30 : before char# 228 in string : "IF %op(%op(%2d,>=,5331),&,%op(%2d,
<=,5340));@00FF $RCIC W%sev U%3c(%2d(1),0);IF %3c(1,0);IF %op(%op(%sev,>=,101),&,%op(%sev,<=,108));@01FF M7F00 %1.ref U5 W0 
"Störungen" U1;endif;endif;IF %op(%sev,>,1"

Resource Allocation

D(1.65) ERR_ASSERT, no:5711  SBS#30 sent ST_RELEASE to SBA#1 state SBA/Operating (1)"sSBA070"

Relates to station 30
The station was released from busy state (Feature, handset off++) but the station has not status of allocated in the subscriber allocator...

SIP

E SIP   Error destination node found in node_map

This message arrives if the destination SIP node in the setup from AlphaCom to SIP is not found in the list of SIP nodes exported from the netrouting system in AlphaPro. The text file of the SIP nodes can be read from SSH in the text file tmp/sip_config.json.

UNEXP_SIG, no:51837  IP_ST#401 sent SIP_START to SBS#401 state SBS/IdleOnIntfCtrl (64)"SBS010" P1: 0, P2: 0, P3: 0 )
UNEXP_SIG, no:51838  TF#1 sent SIP_TERM_TIMER to IP_ST#401 state IP_ST/SIP_st_idle (15)"sip_invite" P1: 0, P2: 0, P3: 0 )

The problem is due to the CRQ Mail Notification on the SIP trunk-station. In this situation the Trunk "user" is blocked for the time of the notification (dut dut dut, 1 second). However this notification is not sent to the SIP trunk, thus could be removed. It is possible to set the station type to CRM for the SIP trunk-station thus avoid notification tone. Another work around is to set the notification time to 0 in the system:

&000964 .ex_profile.timeouts.intf_display_time = 0 (0x0000)

Misc

D(6.65) ERR_ASSERT, no:462  "dt.c" Line: 1107, Bt: 0 0

This kind of message should be really rare and could occur if there is a hardware problem with the backplane.

Trace Event from Interface AMC_CMD_SERVER: Restarting AMC on command

This can either be AlphaWeb -> System Recovery -> Small Reset or Internal “Disaster Assert” from amcd.

Trace Event from Interface AMC_CMD_SERVER: System Reboot

Reboot message can only come from AlphaWeb -> System Recovery -> Reboot.

D(1.65) ERR_ASSERT, no:15229  "glob_state" Line: 741, Bt: 0 0

This is related to a bug in AMC 11.2.3.10. Fixed in 11.2.3.11 See AlphaCom_11.02_-_Release_Notes#Reset_due_to_SysLog_Issues