Could somebody shed some light on what "alarm for adapter index" means? On some occasions I get the following lines repeated in the dialogic log files for hours on end and the system does not answer. Stopping all channels and restarting them usually clears the problem. I find it most often following registration rejections after the system has been running anywhere from an hour or two to 24 hours. The registration time is set to 300 so I know the registration is working fine until then.
We get these quite often but only when they log the DLL_THREAD_ATTACH does the system never respond.
I took a guess that adapter 12 in this case might be network adapter 12. Running ipconfig /all I do see the Windows 7 ipv6 teredo tunneling interface as local area connection 11
System:Windows 7 64bitPowerMedia version 3 service update 310.
gc_h3r SH_MONITOR DEBG mon_decenc.cpp:98 ! 0 ! >> MonDecoder::ProcessRxMsgQueue m_monDecRcvIpc->recvMsg() queue empty.gc_h3r SH_MONITOR DEBG mon_decenc.cpp:127 ! 0 ! << MonDecoder::ProcessRxMsgQueue gc_h3r SH_MONITOR DEBG mon_manager.cpp:152 ! 0 ! >> MonitorMan:CheckInterfaces:monitoring alarm for adapter index 12gc_h3r SH_MONITOR DEBG mon_manager.cpp:200 ! 0 ! << MonitorMan::CheckInterfaces().gc_h3r SH_MONITOR DEBG mon_decenc.cpp:98 ! 0 ! >> MonDecoder::ProcessRxMsgQueue m_monDecRcvIpc->recvMsg() queue empty.gc_h3r SH_MONITOR DEBG mon_decenc.cpp:127 ! 0 ! << MonDecoder::ProcessRxMsgQueue dm3cc DEBG libdm3cc DLL_THREAD_ATTACHdm3cc DEBG libdtidm3.dll DLL_THREAD_ATTACHdm3cc DEBG libdm3cc DLL_THREAD_DETACHdm3cc DEBG libdtidm3.dll DLL_THREAD_DETACH
Shaun, the "monitoring alarm for adapter index..." print is not an error. It is an input from MonitorManager HMP component, which checks the active (the one assigned for signaling) network adapter; you can think of it as monitoring a D-channel on PRI lines. Such check is performed each 4 seconds by default, and if the network cable is unplugged, or the adapter stops functioning, the ALARM event is raised.
There must be some other reason for rejecting calls, and the alarm monitoring has nothing to do with it.
When the system stops receiving calls, do you see any SIP messages hitting the box at all? If the registration fails, the calls may be rejected by your proxy/registrar. Do you see GCEV_SERVICERESP events coming in before the system stops responding?
We thought it was a registration error because no SIP traffic is seen going from the PBX to the system. What we get on our system is the error IPEC_REG_FAIL_internalError on only 4 of the 8 channels, yet the system will not answer. In an attempt to resolve this we now de-register the channel upon receiving this error, wait one minute and then re-register the endpoint, this typically works. However it can take up to 20 minutes of us attempting to register then getting denied and and trying again before we see a successful registration.
Each channel is performing registration to the PBX as a different extension. The strange thing is we only see registration rejections on channels 5,6,7, and 8 and never any other. However once these become completely unregistered no traffic is directed to the system from the PBX.
The PBX is a Mitel 3300 ICP version 10.1.2.16 and this is the second one which has had weird registration issues. On another system we had the exact same thing happen as this forum post http://www.dialogic.com/den/forums/p/6407/24724.aspx#24724 and the only way we resolved it was to swap hardware.
This is a log from when we received an IPEC_REG_FAIL.TIMER - RvTimerQueueService: timer expired(tqueue=03478644; event=03478E38)TRANSPORT - MultiThreadedTimerEventHandler - Allocating timer expired eventTRANSPORT - TransportProcessingQueueAllocateEvent - starting to add event: (hConn=0x0,type=1,bAllo=0)TRANSPORT - TransportProcessingQueueTailEvent - TIMER_EXPIRED_EVENT 0x034A02A8PQUEUE - PQUEUE_TailEvent - (hQueue=0x007EC4F0(StackProcessingQueue) ev=0x034A02A8) notifying threadsPQUEUE - PQUEUE_PopEvent - (hQueue=0x007EC4F0(StackProcessingQueue), *ev=0x034A02A8)=0,TRANSPORT - TransportProcessingQueueDispatchEvents - TIMER_EXPIRED_EVENT 0x034A02A8TIMER - RvTimerQueueService: timer expired(tqueue=03478644; event=03478E38)TRANSACTION - TransactionTimerHandleMainTimerTimeout - Transaction 0x03550730: timer expired (transc state=Client General Request Sent)TRANSMITTER - SipTransmitterRetransmit - Transmitter 0x0353F340 - Retransmitting msg page 0x03703768TRANSPORT - SipTransportUdpSendMessage - Sending message. local-address=192.168.195.9:5060. remote-address=192.168.195.2:5060TRANSPORT - SipTransportUdpSendMessage - sock 1444: Sending UDP message. 192.168.195.9:5060->192.168.195.2:5060, size=450TRANSPORT - --> REGISTER sip:192.168.195.2 SIP/2.0TRANSPORT - From: <sip:2027@192.168.195.2:5060>;tag=354efc0-9c3a8c0-13c4-50022-48f57-107a03b1-48f57TRANSPORT - To: <sip:2027@192.168.195.2:5060>TRANSPORT - Call-ID: 33b6bc8-9c3a8c0-13c4-50022-48f57-409ceae3-48f57TRANSPORT - CSeq: 319 REGISTERTRANSPORT - Via: SIP/2.0/UDP 192.168.195.9:5060;branch=z9hG4bK-5dede-16ee970a-74b38a34TRANSPORT - Max-Forwards: 70TRANSPORT - Supported: replacesTRANSPORT - User-Agent: TestTRANSPORT - Expires: 300TRANSPORT - Contact: <sip:2027@192.168.195.9:5060>TRANSPORT - Content-Length: 0TRANSPORT - TRANSPORT - TransportCallbackMsgToSendEv: Application did not register to call back, default bSendMsg = 1TRANSPORT - TransportCallbackBufferToSend: Application did not register to call back, default *bDiscardBuffer=FALSETRANSMITTER - TransmitterChangeState - transmitter 0x0353F340 - message sent notification on state Msg Sent (reason = Undefined).Don't change stateTRANSMITTER - TransmitterCallbackStateChangeEv: Transmitter 0x0353F340 - Before callbackTRANSACTION - UDPTimersDecide - Transaction 0x03550730: Setting timersTIMER - RvTimerStart: event allocated(tqueue=03478644; timer=035507DC; event=03478F78)TRANSACTION - TransactionTimerSetTimers - Transaction 0x03550730: timer was set to 8000 millisecondsTRANSMITTER - TransmitterCallbackStateChangeEv: Transmitter 0x0353F340,After callbackTRANSMITTER - TransmitterControlTransmitMessage - pTrx=0x0353F340: message 03703768 was sent over UDP (Connection 0x00000000)(rv=0:OK)TRANSACTION - TransactionTransportRetransmitMessage - Transaction 0x03550730: A message was successfully retransmitted.TIMER - RvTimerQueueService: timer expired(tqueue=03478644; event=034788B8)TRANSPORT - MultiThreadedTimerEventHandler - Allocating timer expired eventTRANSPORT - TransportProcessingQueueAllocateEvent - starting to add event: (hConn=0x0,type=1,bAllo=0)TRANSPORT - TransportProcessingQueueTailEvent - TIMER_EXPIRED_EVENT 0x034A0308PQUEUE - PQUEUE_TailEvent - (hQueue=0x007EC4F0(StackProcessingQueue) ev=0x034A0308) notifying threadsPQUEUE - PQUEUE_PopEvent - (hQueue=0x007EC4F0(StackProcessingQueue), *ev=0x034A0308)=0,TRANSPORT - TransportProcessingQueueDispatchEvents - TIMER_EXPIRED_EVENT 0x034A0308
Shaun,
Can you please attach here a log snippet starting from the last successful registration and ending a minute or two after the first IPEC_REG_FAIL? The local wireshark could be helpful, too. From the snippet above I only can guess that the registration fails due to lack of registrar's response.
Attached compressed text log is from 07/31/2012 02:12:02.484 to 07/31/2012 02:23:16.998 with first failure at 2012/07/31-02:21:34:475 according to our logs.
Thanks for the log.
The last successful registration series completed at 02:16:33.519 (see CSeq: 176 REGISTER). Then, upon timer expiration, HMP started a new series (CSeq: 177 REGISTER) at 02:21:02.448. A=By this time something happened to the network, not sure where, but the SIP stack started getting timeouts on UDP communications:
07/31/2012 02:21:34.459 1076 6092 sip_stack Debug INFO - TRANSACTION - TransactionHandleMsgSentFailureEvent - Transaction 0x035D8CE8: Inserting msg send failure (reason=1) to the event queue
07/31/2012 02:21:34.459 1076 6092 sip_stack Debug DEBUG - TRANSC_CLIE - TranscClientChangeState - Transc-client 0x035EFE70 state changed: Activating->Msg Send Failure, (reason = Transaction timeout)
07/31/2012 02:21:34.459 1076 6092 sip_stack Debug DEBUG - REG_CLIENT - RvSipRegClientDNSGetList - reg client 0x035EFE50: getting DNS list07/31/2012 02:21:34.459 1076 6092 sip_stack Debug DEBUG - TRANSC_CLIE - SipTranscClientDNSGetList - transc-client 0x035EFE70: getting DNS list07/31/2012 02:21:34.459 1076 6092 sip_stack Debug DEBUG - TRANSPORT - TransportDNSListGetNumberOfEntries - getting element from list 0x034F802007/31/2012 02:21:34.459 1076 6092 sip_stack Debug DEBUG - TRANSC_CLIE - SipTranscClientGetConnection - pTranscClient 0x035EFE70 - Getting connection 0x0000000007/31/2012 02:21:34.475 1076 6092 gc_h3r SIP_SIGAL DEBG MsgSendFailure.:702 ! 0 ! HandleRegMsgSendFailure: RvSipRegClientGetConnection returned NULL (not tcp)07/31/2012 02:21:34.475 1076 6092 sip_stack Debug DEBUG - REG_CLIENT - RvSipRegClientDNSGiveUp - reg-client 0x035EFE50: giveup DNS07/31/2012 02:21:34.475 1076 6092 sip_stack Debug DEBUG - TRANSC_CLIE - SipTranscClientDNSGiveUp - Transc-client 0x035EFE70: giveup DNS
As result, the error was raised internally, and the app received a notification.
I see no problem with the application or HMP actions, but rather some network failure. Here may be different reasons for the failure, internal and external, like UDP port conflict on the HMP server (someone else binds UDP port 5060 exclusively), local network failure, DNS failure and others. I can't see it from the log; I believe, wireshark trace may help here; at least we'll see if any message was sent from the server when the troubles begin.
Can you run wireshark locally or on the nearest router's mirror port?
Should have posted this along with the logs, was not really thinking. This is the wireshark log during that same time period.
It looks like the problem starts around 2:16:33 following a registration of all the channels the dialogic log show multiple TransportProcessingQueueDispatchEvents - TIMER_EXPIRED_EVENT 0x03530468 events and then lots of these alaram for adapter errors until the system attempts to re-register in after the 300 second time out.
So at the same time the dialogic logs show it is attempting to register at 2:21:02 wireshark shows no attempt for registration but has endless amounts of broadcasts messages coming from the local nic requesting who has the IP address associated with the PBX.
This problem occurs within an hour each and every day and only once a day.
After repeatedly asking the customer over a period of four weeks if the network or PBX is being shutdown during this time period with no response, they finally admitted that the PBX was configured to restart at 2:15 every night and takes up to 30 minutes to restart.
Thank you for your help.
