Cisco Support Community
cancel
Showing results for 
Search instead for 
Did you mean: 
New Member

spa400 are constantly reboot

Jun 29 13:01:30 10.22.2.5 0081567229 - Global initialization done.^M
Jun 29 13:01:36 10.22.2.5 0081570640 - UTIL: Going to parse MDMF type CID info^M
Jun 29 13:01:36 10.22.2.5 0081570640 - UTIL: got raw msg = ^A^H06291259^B 8181021157, length=22^M
Jun 29 13:01:36 10.22.2.5 0081570641 - UTIL: param type=1 ^M
Jun 29 13:01:36 10.22.2.5 0081570641 - UTIL: time=06291259^M
Jun 29 13:01:36 10.22.2.5 0081570641 - UTIL: param type=2 ^M
Jun 29 13:01:36 10.22.2.5 0081570641 - UTIL: number=8181021157^M
Jun 29 13:01:38 10.22.2.5 0081571310 - TIU: Reset ETSI FSK CID on 0^M
Jun 29 13:01:38 10.22.2.5 0081571320 - TIU: Set ETSI FSK CID on 0^M
Jun 29 13:01:40 10.22.2.5 0081572343 - LSS: 0 fake in_use state, got a real ringing^M
Jun 29 13:01:40 10.22.2.5 0081572349 - ASSERT failure in file sfucalls.c at line 531^M
Jun 29 13:01:41 10.22.2.5 0081572859 - *** VMS fail, USB SD does not have dir /var/mnt/spa400vm/var/spool ^M
Jun 29 13:01:41 10.22.2.5 0081572864 - ast_main done USB: 0, vms: -2 ^M
Jun 29 13:01:41 10.22.2.5 0081572868 - Global initialization done.^M
Jun 29 13:01:41 10.22.2.5 0081573062 - TIU: Reset ETSI FSK CID on 2^M
Jun 29 13:01:41 10.22.2.5 0081573072 - TIU: Set ETSI FSK CID on 2^M
Jun 29 13:02:18 10.22.2.5 0000008901 - SYSLOG: hadong, network syslog initial done^M
Jun 29 13:02:19 10.22.2.5 0000009387 - ERROR  - LI           - LI_Open: paul bind. socket=24, port=5060 (502160a)^M
Jun 29 13:02:19 10.22.2.5 0000009389 - ERROR  - LI           - LI_Open: paul bind. socket=25, port=5060 (502160a)^M
Jun 29 13:02:19 10.22.2.5 0000009569 - ============================================================^M
Jun 29 13:02:19 10.22.2.5 0000009570 - SSMU Inited RV SIP Stack Version 3.0.5.1 successfully!!^M
Jun 29 13:02:19 10.22.2.5 0000009570 - ============================================================^M
Jun 29 13:02:20 10.22.2.5 0000009824 - *** VMS fail, USB SD does not have dir /var/mnt/spa400vm/var/spool ^M
Jun 29 13:02:20 10.22.2.5 0000009832 - ast_main done USB: 0, vms: -2 ^M
Jun 29 13:02:20 10.22.2.5 0000009835 - Global initialization done.^M
Jun 29 13:02:20 10.22.2.5 0000009841 - TIU: All FXO port get a state^M
Jun 29 13:02:22 10.22.2.5 0000010843 - TIU: Set DSP as ETSI FSK on 0^M
Jun 29 13:02:22 10.22.2.5 0000010844 - TIU: Set DSP as ETSI FSK on 1^M
Jun 29 13:02:22 10.22.2.5 0000010845 - TIU: Set DSP as ETSI FSK on 2^M
Jun 29 13:02:22 10.22.2.5 0000010845 - TIU: Set DSP as ETSI FSK on 3^M
--------------------------------------

Jun 29 15:06:57 10.22.2.5 0003749259 - UTIL: Going to parse MDMF type CID info^M
Jun 29 15:06:57 10.22.2.5 0003749259 - UTIL: got raw msg = ^A^H06291504^B 8112126711, length=22^M
Jun 29 15:06:57 10.22.2.5 0003749259 - UTIL: param type=1 ^M
Jun 29 15:06:57 10.22.2.5 0003749260 - UTIL: time=06291504^M
Jun 29 15:06:57 10.22.2.5 0003749260 - UTIL: param type=2 ^M
Jun 29 15:06:57 10.22.2.5 0003749260 - UTIL: number=8112126711^M
Jun 29 15:07:01 10.22.2.5 0003750962 - LSS: 0 fake in_use state, got a real ringing^M
Jun 29 15:07:01 10.22.2.5 0003750967 - ASSERT failure in file sfucalls.c at line 531^M
Jun 29 15:07:39 10.22.2.5 0000008869 - SYSLOG: hadong, network syslog initial done^M
Jun 29 15:07:40 10.22.2.5 0000009354 - ERROR  - LI           - LI_Open: paul bind. socket=24, port=5060 (502160a)^M
Jun 29 15:07:40 10.22.2.5 0000009356 - ERROR  - LI           - LI_Open: paul bind. socket=25, port=5060 (502160a)^M
Jun 29 15:07:40 10.22.2.5 0000009534 - ============================================================^M
Jun 29 15:07:40 10.22.2.5 0000009534 - SSMU Inited RV SIP Stack Version 3.0.5.1 successfully!!^M
Jun 29 15:07:40 10.22.2.5 0000009534 - ============================================================^M
Jun 29 15:07:42 10.22.2.5 0000010238 - Port = 0^M
Jun 29 15:07:44 10.22.2.5 0000011618 - SSMU: *** ssmup_state_free - failed to open rtp/rtcp port,                      cb-id: 0^M
Jun 29 15:07:45 10.22.2.5 0000011644 - SSMU 0: State machine Unexpected event NW_DISCONNECTED in IDLE state^M
Jun 29 15:07:45 10.22.2.5 0000011968 - *** VMS fail, USB SD does not have dir /var/mnt/spa400vm/var/spool ^M
Jun 29 15:07:45 10.22.2.5 0000011971 - ast_main done USB: 0, vms: -2 ^M
Jun 29 15:07:45 10.22.2.5 0000011973 - Global initialization done.^M
Jun 29 15:07:45 10.22.2.5 0000011978 - TIU: All FXO port get a state^M
Jun 29 15:07:46 10.22.2.5 0000012453 - TIU: 1st FXO state report sent^M
Jun 29 15:07:46 10.22.2.5 0000012469 - TIU: Set DSP as ETSI FSK on 0^M
Jun 29 15:07:47 10.22.2.5 0000012980 - TIU: Set DSP as ETSI FSK on 1^M
Jun 29 15:07:47 10.22.2.5 0000012982 - TIU: Set DSP as ETSI FSK on 2^M
Jun 29 15:07:47 10.22.2.5 0000012983 - TIU: Set DSP as ETSI FSK on 3^M
Jun 29 15:07:47 10.22.2.5 0000013090 - TIU: Set DSP as ETSI FSK on 0^M
---------------------------------------

Jun 30 14:05:15 10.22.2.5 0041345224 - UTIL: Going to parse MDMF type CID info^M
Jun 30 14:05:15 10.22.2.5 0041345224 - UTIL: got raw msg = ^A^H06301403^B 8181021157, length=22^M
Jun 30 14:05:15 10.22.2.5 0041345224 - UTIL: param type=1 ^M
Jun 30 14:05:15 10.22.2.5 0041345225 - UTIL: time=06301403^M
Jun 30 14:05:15 10.22.2.5 0041345225 - UTIL: param type=2 ^M
Jun 30 14:05:15 10.22.2.5 0041345225 - UTIL: number=8181021157^M
Jun 30 14:05:18 10.22.2.5 0041346931 - LSS: 0 fake in_use state, got a real ringing^M
Jun 30 14:05:18 10.22.2.5 0041346936 - ASSERT failure in file sfucalls.c at line 531^M
Jun 30 14:05:57 10.22.2.5 0000009067 - SYSLOG: hadong, network syslog initial done^M
Jun 30 14:05:58 10.22.2.5 0000009549 - ERROR  - LI           - LI_Open: paul bind. socket=24, port=5060 (502160a)^M
Jun 30 14:05:58 10.22.2.5 0000009551 - ERROR  - LI           - LI_Open: paul bind. socket=25, port=5060 (502160a)^M
Jun 30 14:05:58 10.22.2.5 0000009742 - ============================================================^M
Jun 30 14:05:58 10.22.2.5 0000009743 - SSMU Inited RV SIP Stack Version 3.0.5.1 successfully!!^M
Jun 30 14:05:58 10.22.2.5 0000009743 - ============================================================^M
Jun 30 14:05:59 10.22.2.5 0000010010 - *** VMS fail, USB SD does not have dir /var/mnt/spa400vm/var/spool ^M
Jun 30 14:05:59 10.22.2.5 0000010013 - ast_main done USB: 0, vms: -2 ^M
Jun 30 14:05:59 10.22.2.5 0000010015 - Global initialization done.^M
Jun 30 14:05:59 10.22.2.5 0000010024 - TIU: All FXO port get a state^M
Jun 30 14:06:01 10.22.2.5 0000011026 - TIU: Set DSP as ETSI FSK on 0^M
Jun 30 14:06:01 10.22.2.5 0000011027 - TIU: Set DSP as ETSI FSK on 1^M
Jun 30 14:06:01 10.22.2.5 0000011028 - TIU: Set DSP as ETSI FSK on 2^M
Jun 30 14:06:01 10.22.2.5 0000011029 - TIU: Set DSP as ETSI FSK on 3^M
---------------------------------------------------

Jul  1 09:19:25 10.22.2.5 0034598977 - TIU: Reset ETSI FSK CID on 0^M
Jul  1 09:19:25 10.22.2.5 0034598987 - TIU: Set ETSI FSK CID on 0^M
Jul  1 09:19:29 10.22.2.5 0034601231 - UTIL: Going to parse MDMF type CID info^M
Jul  1 09:19:29 10.22.2.5 0034601231 - UTIL: got raw msg = ^A^H07010916^B 8180310000, length=22^M
Jul  1 09:19:29 10.22.2.5 0034601231 - UTIL: param type=1 ^M
Jul  1 09:19:29 10.22.2.5 0034601232 - UTIL: time=07010916^M
Jul  1 09:19:29 10.22.2.5 0034601232 - UTIL: param type=2 ^M
Jul  1 09:19:29 10.22.2.5 0034601232 - UTIL: number=8180310000^M
Jul  1 09:19:33 10.22.2.5 0034602941 - LSS: 0 fake in_use state, got a real ringing^M
Jul  1 09:19:33 10.22.2.5 0034602961 - ASSERT failure in file sfucalls.c at line 531^M
Jul  1 09:19:34 10.22.2.5 0034603621 - *** VMS fail, USB SD does not have dir /var/mnt/spa400vm/var/spool ^M
Jul  1 09:19:34 10.22.2.5 0034603631 - ast_main done USB: 0, vms: -2 ^M
Jul  1 09:19:34 10.22.2.5 0034603641 - Global initialization done.^M
Jul  1 09:20:11 10.22.2.5 0000008783 - SYSLOG: hadong, network syslog initial done^M
Jul  1 09:20:12 10.22.2.5 0000009267 - ERROR  - LI           - LI_Open: paul bind. socket=24, port=5060 (502160a)^M
Jul  1 09:20:12 10.22.2.5 0000009269 - ERROR  - LI           - LI_Open: paul bind. socket=25, port=5060 (502160a)^M
Jul  1 09:20:13 10.22.2.5 0000009448 - ============================================================^M
Jul  1 09:20:13 10.22.2.5 0000009448 - SSMU Inited RV SIP Stack Version 3.0.5.1 successfully!!^M
Jul  1 09:20:13 10.22.2.5 0000009448 - ============================================================^M
Jul  1 09:20:13 10.22.2.5 0000009775 - *** VMS fail, USB SD does not have dir /var/mnt/spa400vm/var/spool ^M
Jul  1 09:20:13 10.22.2.5 0000009777 - ast_main done USB: 0, vms: -2 ^M
Jul  1 09:20:13 10.22.2.5 0000009779 - Global initialization done.^M
Jul  1 09:20:13 10.22.2.5 0000009786 - TIU: All FXO port get a state^M
Jul  1 09:20:15 10.22.2.5 0000010788 - TIU: Set DSP as ETSI FSK on 0^M
Jul  1 09:20:15 10.22.2.5 0000010789 - TIU: Set DSP as ETSI FSK on 1^M
Jul  1 09:20:15 10.22.2.5 0000010790 - TIU: Set DSP as ETSI FSK on 2^M
Jul  1 09:20:16 10.22.2.5 0000010965 - TIU: Set DSP as ETSI FSK on 3^M
Jul  1 09:20:25 10.22.2.5 0000015765 - TIU: Set DSP as ETSI FSK on 3^M
------------------------------------------------------------

Jul  1 17:27:55 10.22.2.5 0014643717 - UTIL: Going to parse MDMF type CID info^M
Jul  1 17:27:55 10.22.2.5 0014643717 - UTIL: got raw msg = ^A^H07011725^B 8111015220, length=22^M
Jul  1 17:27:55 10.22.2.5 0014643718 - UTIL: param type=1 ^M
Jul  1 17:27:55 10.22.2.5 0014643718 - UTIL: time=07011725^M
Jul  1 17:27:55 10.22.2.5 0014643718 - UTIL: param type=2 ^M
Jul  1 17:27:55 10.22.2.5 0014643718 - UTIL: number=8111015220^M
Jul  1 17:27:56 10.22.2.5 0014644166 - *** VMS fail, USB SD does not have dir /var/mnt/spa400vm/var/spool ^M
Jul  1 17:27:56 10.22.2.5 0014644172 - ast_main done USB: 0, vms: -2 ^M
Jul  1 17:27:56 10.22.2.5 0014644176 - Global initialization done.^M
Jul  1 17:27:58 10.22.2.5 0014645416 - LSS: 3 fake in_use state, got a real ringing^M
Jul  1 17:27:58 10.22.2.5 0014645426 - ASSERT failure in file sfucalls.c at line 531^M
Jul  1 17:28:00 10.22.2.5 0014646421 - Port = 0^M
Jul  1 17:28:37 10.22.2.5 0000008974 - SYSLOG: hadong, network syslog initial done^M
Jul  1 17:28:38 10.22.2.5 0000009459 - ERROR  - LI           - LI_Open: paul bind. socket=24, port=5060 (502160a)^M
Jul  1 17:28:38 10.22.2.5 0000009461 - ERROR  - LI           - LI_Open: paul bind. socket=25, port=5060 (502160a)^M
Jul  1 17:28:38 10.22.2.5 0000009645 - ============================================================^M
Jul  1 17:28:38 10.22.2.5 0000009646 - SSMU Inited RV SIP Stack Version 3.0.5.1 successfully!!^M
Jul  1 17:28:38 10.22.2.5 0000009646 - ============================================================^M
Jul  1 17:28:39 10.22.2.5 0000009960 - *** VMS fail, USB SD does not have dir /var/mnt/spa400vm/var/spool ^M
Jul  1 17:28:39 10.22.2.5 0000009962 - ast_main done USB: 0, vms: -2 ^M
Jul  1 17:28:39 10.22.2.5 0000009965 - Global initialization done.^M
Jul  1 17:28:39 10.22.2.5 0000009972 - TIU: All FXO port get a state^M
Jul  1 17:28:41 10.22.2.5 0000011003 - Port = 0^M
Jul  1 17:28:42 10.22.2.5 0000011586 - TIU: Set DSP as ETSI FSK on 1^M
Jul  1 17:28:42 10.22.2.5 0000011587 - TIU: Set DSP as ETSI FSK on 2^M
Jul  1 17:28:42 10.22.2.5 0000011588 - TIU: Set DSP as ETSI FSK on 3^M
---------------------------------------------------------

Everyone's tags (1)
18 REPLIES
Cisco Employee

Re: spa400 are constantly reboot

Dear Sir;

One question

- What FW version are you using on the SPA400?

There seems to be an issue with the files in the VM. I suggest you rebuild the USB drive according to: /docs/DOC-9869

Regards
Alberto

New Member

Re: spa400 are constantly reboot

Firmware Version: 1.1.2.2

did not have installed the usb, put him yesterday afternoon. 

sounds to me a problem with the CID, for this line  :


Jun 29 13:01:40 10.22.2.5 0081572349 - Assert failure in sfucalls.c file at line 531


and always reboot when a incoming call.

Cisco Employee

Re: spa400 are constantly reboot

Hi galmague1

If this is a new installation, consider factory resetting the SPA400 and then using the new beta-version of the SPA9000 Setup Wizard to configure the SPA9000 and the SPA400.

The Wizard is available from here:

https://www.myciscocommunity.com/docs/DOC-8126

Regards,

Patrick

----------

New Member

Re: spa400 are constantly reboot

I'm using asterisk. 

after setting the usb is still reboot. 

the difference between mine and the default is the following: 

default 

mine: 
> H_DC_limit = 0 
> H_Caller_id = 3

Cisco Employee

Re: spa400 are constantly reboot

Dear Sir;

One question is why are you changing the DC value to disabled?

Could you please test the attached the test firmware to see if it resolves the issue?

Regards
Alberto

New Member

Re: spa400 are constantly reboot

well for 3 days but failed again today.

Jul 13 10:32:46 10.22.2.5 0129356168 - TIU: Set ETSI FSK CID on 0^M
Jul 13 10:32:56 10.22.2.5 0129361405 - TIU: Set DSP as ETSI FSK on 3^M
Jul 13 10:32:57 10.22.2.5 0129361801 - UTIL: Going to parse MDMF type CID info^M
Jul 13 10:32:57 10.22.2.5 0129361801 - UTIL: got raw msg = ^A^H07131032^B 8183760546, length=22^M
Jul 13 10:32:57 10.22.2.5 0129361801 - UTIL: param type=1 ^M
Jul 13 10:32:57 10.22.2.5 0129361802 - UTIL: time=07131032^M
Jul 13 10:32:57 10.22.2.5 0129361802 - UTIL: param type=2 ^M
Jul 13 10:32:57 10.22.2.5 0129361802 - UTIL: number=8183760546^M
Jul 13 10:33:01 10.22.2.5 0129363510 - LSS: 0 fake in_use state, got a real ringing^M
Jul 13 10:33:01 10.22.2.5 0129363515 - ASSERT failure in file sfucalls.c at line 531^M
Jul 13 10:33:02 10.22.2.5 0129364369 - TIU: Reset ETSI FSK CID on 2^M
Jul 13 10:33:02 10.22.2.5 0129364379 - TIU: Set ETSI FSK CID on 2^M
Jul 13 10:33:40 10.22.2.5 0000009498 - SYSLOG: hadong, network syslog initial done^M
Jul 13 10:33:41 10.22.2.5 0000009718 - Dst applied, offset:1247499348 , iSave:220156320^M
Jul 13 10:33:42 10.22.2.5 0000010142 -   == Parsing '/var/asterisk.conf': ^M
Jul 13 10:33:42 10.22.2.5 0000010144 - Found ^M


3 days without a reboot is a record!

that these lines?

ASSERT failure in file sfucalls.c at line 531

Can help find the problem?
Cisco Employee

Re: spa400 are constantly reboot

Hi galmague1,

We're trying to recreate the problem that you report and need your help please.

1. How do you have the SPA400 configured?

2. How do you have Asterisk configured?

3. How do  you make calls through the SPA400

4. Please provide more syslog information

Please send the above information to me at paborn at Cisco.com and I'll share with Engineering.

Regards,

Patrick

-----------

New Member

Re: spa400 are constantly reboot

Last week I had 2 reboots for the following reason "Cannot allocate packet - tsg_get_voice_data_buf()", one was at 3 am (when no one spoke on the phone)



---- last 5 sec before reboot
Jul 17 11:36:40 10.22.2.5 0062251117 - TIU: 3 FXO voltage changed, state on, voltage 63V -> 38V^M
Jul 17 11:36:40 10.22.2.5 0062251188 - RTCP: 1, rtcpp_pkt_from_net^M
Jul 17 11:36:41 10.22.2.5 0062251262 - RTCP: 2, received RXTX stats^M
Jul 17 11:36:41 10.22.2.5 0062251262 - RTCP: 2, rtcpp_send_pkt, call_back: 0x0^M
Jul 17 11:36:41 10.22.2.5 0062251263 - RTCP: 2, rtcpp_send_encrypt_eligible_pkt^M
Jul 17 11:36:41 10.22.2.5 0062251263 - PSU: *** psup_util_lookup_ccb - call ref 0002003a NOT found^M
Jul 17 11:36:41 10.22.2.5 0062251263 - PSU: *** psup_proc_smc2_data - invalid ccb - type  5^M
Jul 17 11:36:41 10.22.2.5 0062251279 - SPU: 3, Voice band data detection started^M
Jul 17 11:36:41 10.22.2.5 0062251379 - UTIL: Going to parse MDMF type CID info^M
Jul 17 11:36:41 10.22.2.5 0062251379 - UTIL: got raw msg = ^A^H07171134^B 8117161362, length=22^M
Jul 17 11:36:41 10.22.2.5 0062251380 - UTIL: param type=1 ^M
Jul 17 11:36:41 10.22.2.5 0062251380 - UTIL: time=07171134^M
Jul 17 11:36:41 10.22.2.5 0062251380 - UTIL: param type=2 ^M
Jul 17 11:36:41 10.22.2.5 0062251380 - UTIL: number=8117161362^M
Jul 17 11:36:41 10.22.2.5 0062251387 - SPU: 3, Caller ID detection result = 0^M
Jul 17 11:36:41 10.22.2.5 0062251387 - George: FSK Caller ID Info Detected on TCID 3:^M
Jul 17 11:36:41 10.22.2.5 0062251388 - SPU: Date =  0 7/ 1 7^M
Jul 17 11:36:41 10.22.2.5 0062251388 - SPU: Time =  1 1: 3 4^M
Jul 17 11:36:41 10.22.2.5 0062251388 - SPU: Calling Number = 8117161362 ^M
Jul 17 11:36:41 10.22.2.5 0062251388 - SPU: Calling Party Name = No Name ^M
Jul 17 11:36:41 10.22.2.5 0062251557 - RTCP: 3, received RXTX stats^M
Jul 17 11:36:41 10.22.2.5 0062251557 - RTCP: 3, rtcpp_send_pkt, call_back: 0x0^M
Jul 17 11:36:41 10.22.2.5 0062251558 - RTCP: 3, rtcpp_send_encrypt_eligible_pkt^M
Jul 17 11:36:41 10.22.2.5 0062251558 - PSU: *** psup_util_lookup_ccb - call ref 00000052 NOT found^M
Jul 17 11:36:41 10.22.2.5 0062251558 - PSU: *** psup_proc_smc1_data - invalid ccb - type  5^M
Jul 17 11:36:42 10.22.2.5 0062252117 - TIU: 3 FXO voltage changed, state on, voltage 38V -> 47V^M
Jul 17 11:36:44 10.22.2.5 0062253009 - DIM: 0:0 - MGB_DM_TONE_DETECT: Tone Id: 3^M
Jul 17 11:36:44 10.22.2.5 0062253009 - CCU: 1, tone_detect_api on_off = 1 map to: 1^M
Jul 17 11:36:44 10.22.2.5 0062253013 - ISU: 1, Tone Detect tone=3 on=1 timestamp=55539 power=-22 1st freq=261 2nd freq=530^M
Jul 17 11:36:44 10.22.2.5 0062253013 - ISU: 1, the tone detected is a CP tone^M
Jul 17 11:36:44 10.22.2.5 0062253013 - ISU: 1, Call progress tone ON^M
Jul 17 11:36:44 10.22.2.5 0062253017 - ISU: 1, isup_cp_tone_elem_process_event, det 0, elem 0(on_cad) gets event tone_on^M
Jul 17 11:36:44 10.22.2.5 0062253017 - ISU: 1, isup_cp_tone_det_process_event, det 0, elem 0(on_cad) returned start_timer^M
Jul 17 11:36:44 10.22.2.5 0062253017 - ISU: 1, isup_cp_tone_det_process_event, det 0, elem 0(on_cad) timeout value = 2300^M
Jul 17 11:36:44 10.22.2.5 0062253018 - ISU: 1, isup_cp_tone_elem_process_event, det 1, elem 0(on_cad) gets event tone_on^M
Jul 17 11:36:44 10.22.2.5 0062253018 - ISU: 1, isup_cp_tone_det_process_event, det 1, elem 0(on_cad) returned start_timer^M
Jul 17 11:36:44 10.22.2.5 0062253018 - ISU: 1, isup_cp_tone_det_process_event, det 1, elem 0(on_cad) timeout value = 60000^M
Jul 17 11:36:44 10.22.2.5 0062253018 - ISU: 1, isup_cp_tone_elem_process_event, det 2, elem 0(on_cad) gets event tone_on^M
Jul 17 11:36:44 10.22.2.5 0062253022 - ISU: 1, isup_cp_tone_det_process_event, det 2, elem 0(on_cad) returned start_timer^M
Jul 17 11:36:44 10.22.2.5 0062253023 - ISU: 1, isup_cp_tone_det_process_event, det 2, elem 0(on_cad) timeout value = 1800^M
Jul 17 11:36:44 10.22.2.5 0062253023 - ISU: 1, isup_cp_tone_elem_process_event, det 3, elem 0(on_cad) gets event tone_on^M
Jul 17 11:36:44 10.22.2.5 0062253023 - ISU: 1, isup_cp_tone_det_process_event, det 3, elem 0(on_cad) returned start_timer^M
Jul 17 11:36:44 10.22.2.5 0062253027 - ISU: 1, isup_cp_tone_det_process_event, det 3, elem 0(on_cad) timeout value = 900^M
Jul 17 11:36:44 10.22.2.5 0062253027 - ISU: 1, isup_cp_tone_elem_process_event, det 4, elem 0(on_cad) gets event tone_on^M
Jul 17 11:36:44 10.22.2.5 0062253027 - ISU: 1, isup_cp_tone_det_process_event, det 4, elem 0(on_cad) returned start_timer^M
Jul 17 11:36:44 10.22.2.5 0062253028 - ISU: 1, isup_cp_tone_det_process_event, det 4, elem 0(on_cad) timeout value = 720^M
Jul 17 11:36:44 10.22.2.5 0062253028 - ISU: 1, isup_cp_tone_elem_process_event, det 5, elem 0(on_cad) gets event tone_on^M
Jul 17 11:36:44 10.22.2.5 0062253028 - ISU: 1, isup_cp_tone_det_process_event, det 5, elem 0(on_cad) returned start_timer^M
Jul 17 11:36:44 10.22.2.5 0062253032 - ISU: 1, isup_cp_tone_det_process_event, det 5, elem 0(on_cad) timeout value = 450^M
Jul 17 11:36:44 10.22.2.5 0062253032 - ISU: 1, isup_cp_tone_elem_process_event, det 6, elem 0(on_cad) gets event tone_on^M
Jul 17 11:36:44 10.22.2.5 0062253033 - ISU: 1, isup_cp_tone_det_process_event, det 6, elem 0(on_cad) returned start_timer^M
Jul 17 11:36:44 10.22.2.5 0062253033 - ISU: 1, isup_cp_tone_det_process_event, det 6, elem 0(on_cad) timeout value = 225^M
Jul 17 11:36:44 10.22.2.5 0062253032 - ISU: 1, isup_cp_tone_elem_process_event, det 6, elem 0(on_cad) gets event tone_on^M
Jul 17 11:36:44 10.22.2.5 0062253033 - ISU: 1, isup_cp_tone_det_process_event, det 6, elem 0(on_cad) returned start_timer^M
Jul 17 11:36:44 10.22.2.5 0062253033 - ISU: 1, isup_cp_tone_det_process_event, det 6, elem 0(on_cad) timeout value = 225^M
Jul 17 11:36:44 10.22.2.5 0062253033 - ISU: 1, Call progress detection timer started, period = 0 ms^M
Jul 17 11:36:44 10.22.2.5 0062253034 - DIM: 0:0 - MGB_DM_TONE_DETECT: Tone Id: 3^M
Jul 17 11:36:44 10.22.2.5 0062253034 - CCU: 1, tone_detect_api on_off = 0 map to: 1^M
Jul 17 11:36:44 10.22.2.5 0062253038 - ISU: 1, Call progress detection timer expired^M
Jul 17 11:36:44 10.22.2.5 0062253038 - ISU: 1, isup_cp_tone_elem_process_event, det 6, elem 0(on_cad) gets event timer_exp^M
Jul 17 11:36:44 10.22.2.5 0062253038 - ISU: 1, isup_cp_tone_det_process_event, det 6, elem 0(on_cad) returned start_timer^M
Jul 17 11:36:44 10.22.2.5 0062253042 - ISU: 1, isup_cp_tone_det_process_event, det 6, elem 0(on_cad) timeout value = 275^M
Jul 17 11:36:44 10.22.2.5 0062253042 - ISU: 1, Call progress detection timer started, period = 26 ms^M
Jul 17 11:36:44 10.22.2.5 0062253043 - ISU: 1, Tone Detect tone=3 on=0 timestamp=55779 power=-23 1st freq=261 2nd freq=530^M
Jul 17 11:36:44 10.22.2.5 0062253043 - ISU: 1, the tone detected is a CP tone^M
Jul 17 11:36:44 10.22.2.5 0062253043 - ISU: 1, Call progress tone OFF^M
Jul 17 11:36:44 10.22.2.5 0062253043 - ISU: 1, Call progress detection timer aborted^M
Jul 17 11:36:44 10.22.2.5 0062253047 - ISU: 1, isup_cp_tone_elem_process_event, det 0, elem 0(on_cad) gets event tone_off^M
Jul 17 11:36:44 10.22.2.5 0062253047 - ISU: 1, isup_cp_tone_det_process_event, det 0, elem 0(on_cad) returned reset^M
Jul 17 11:36:44 10.22.2.5 0062253047 - ISU: 1, isup_cp_tone_det_process_event, det 0, next element = 0^M
Jul 17 11:36:44 10.22.2.5 0062253048 - ISU: 1, isup_cp_tone_elem_process_event, det 0, elem 0(on_cad) gets event init^M
Jul 17 11:36:44 10.22.2.5 0062253048 - ISU: 1, isup_cp_tone_elem_process_event, det 0, elem 0(on_cad) gets event tone_off^M
Jul 17 11:36:44 10.22.2.5 0062253048 - ISU: 1, isup_cp_tone_det_process_event, det 0, elem 0(on_cad) returned none^M
Jul 17 11:36:44 10.22.2.5 0062253049 - ISU: 1, isup_cp_tone_elem_process_event, det 1, elem 0(on_cad) gets event tone_off^M
Jul 17 11:36:44 10.22.2.5 0062253052 - ISU: 1, isup_cp_tone_det_process_event, det 1, elem 0(on_cad) returned reset^M
Jul 17 11:36:44 10.22.2.5 0062253053 - ISU: 1, isup_cp_tone_det_process_event, det 1, next element = 0^M
Jul 17 11:36:44 10.22.2.5 0062253053 - ISU: 1, isup_cp_tone_elem_process_event, det 1, elem 0(on_cad) gets event init^M
Jul 17 11:36:44 10.22.2.5 0062253053 - ISU: 1, isup_cp_tone_elem_process_event, det 1, elem 0(on_cad) gets event tone_off^M
Jul 17 11:36:44 10.22.2.5 0062253053 - ISU: 1, isup_cp_tone_det_process_event, det 1, elem 0(on_cad) returned none^M
Jul 17 11:36:44 10.22.2.5 0062253057 - ISU: 1, isup_cp_tone_elem_process_event, det 2, elem 0(on_cad) gets event tone_off^M
Jul 17 11:36:44 10.22.2.5 0062253057 - ISU: 1, isup_cp_tone_det_process_event, det 2, elem 0(on_cad) returned reset^M
Jul 17 11:36:44 10.22.2.5 0062253058 - ISU: 1, isup_cp_tone_det_process_event, det 2, next element = 0^M
Jul 17 11:36:44 10.22.2.5 0062253058 - ISU: 1, isup_cp_tone_elem_process_event, det 2, elem 0(on_cad) gets event init^M
Jul 17 11:36:44 10.22.2.5 0062253058 - ISU: 1, isup_cp_tone_elem_process_event, det 2, elem 0(on_cad) gets event tone_off^M
Jul 17 11:36:44 10.22.2.5 0062253058 - ISU: 1, isup_cp_tone_det_process_event, det 2, elem 0(on_cad) returned none^M
Jul 17 11:36:44 10.22.2.5 0062253062 - ISU: 1, isup_cp_tone_elem_process_event, det 3, elem 0(on_cad) gets event tone_off^M
Jul 17 11:36:44 10.22.2.5 0062253062 - ISU: 1, isup_cp_tone_det_process_event, det 3, elem 0(on_cad) returned reset^M
Jul 17 11:36:44 10.22.2.5 0062253063 - ISU: 1, isup_cp_tone_det_process_event, det 3, next element = 0^M
Jul 17 11:36:44 10.22.2.5 0062253063 - ISU: 1, isup_cp_tone_elem_process_event, det 3, elem 0(on_cad) gets event init^M
Jul 17 11:36:44 10.22.2.5 0062253063 - ISU: 1, isup_cp_tone_elem_process_event, det 3, elem 0(on_cad) gets event tone_off^M
Jul 17 11:36:44 10.22.2.5 0062253067 - ISU: 1, isup_cp_tone_det_process_event, det 3, elem 0(on_cad) returned none^M
Jul 17 11:36:44 10.22.2.5 0062253067 - ISU: 1, isup_cp_tone_elem_process_event, det 4, elem 0(on_cad) gets event tone_off^M
Jul 17 11:36:44 10.22.2.5 0062253068 - ISU: 1, isup_cp_tone_det_process_event, det 4, elem 0(on_cad) returned reset^M
Jul 17 11:36:44 10.22.2.5 0062253068 - ISU: 1, isup_cp_tone_det_process_event, det 4, next element = 0^M
Jul 17 11:36:44 10.22.2.5 0062253068 - ISU: 1, isup_cp_tone_elem_process_event, det 4, elem 0(on_cad) gets event init^M
Jul 17 11:36:44 10.22.2.5 0062253069 - CCU: Cannot allocate packet - tsg_get_voice_data_buf()^M
Jul 17 11:36:44 10.22.2.5 0062253068 - ISU: 1, isup_cp_tone_elem_process_event, det 4, elem 0(on_cad) gets event tone_off^M
Jul 17 11:36:44 10.22.2.5 0062253072 - ISU: 1, isup_cp_tone_det_process_event, det 4, elem 0(on_cad) returned none^M
Jul 17 11:36:44 10.22.2.5 0062253073 - ISU: 1, isup_cp_tone_elem_process_event, det 5, elem 0(on_cad) gets event tone_off^M
Jul 17 11:36:44 10.22.2.5 0062253073 - ISU: 1, isup_cp_tone_det_process_event, det 5, elem 0(on_cad) returned reset^M
Jul 17 11:36:44 10.22.2.5 0062253073 - ISU: 1, isup_cp_tone_det_process_event, det 5, next element = 0^M
Jul 17 11:36:44 10.22.2.5 0062253077 - ISU: 1, isup_cp_tone_elem_process_event, det 5, elem 0(on_cad) gets event init^M
Jul 17 11:36:44 10.22.2.5 0062253077 - ISU: 1, isup_cp_tone_elem_process_event, det 5, elem 0(on_cad) gets event tone_off^M
Jul 17 11:36:44 10.22.2.5 0062253077 - ISU: 1, isup_cp_tone_det_process_event, det 5, elem 0(on_cad) returned none^M
Jul 17 11:36:44 10.22.2.5 0062253078 - ISU: 1, isup_cp_tone_elem_process_event, det 6, elem 0(on_cad) gets event tone_off^M
Jul 17 11:36:44 10.22.2.5 0062253078 - ISU: 1, isup_cp_tone_det_process_event, det 6, elem 0(on_cad) returned iterate_next^M
Jul 17 11:36:44 10.22.2.5 0062253078 - ISU: 1, isup_cp_tone_det_process_event, det 6, next element = 1^M
Jul 17 11:36:44 10.22.2.5 0062253104 - ISU: 1, isup_cp_tone_elem_process_event, det 6, elem 1(off_cad) gets event init^M
Jul 17 11:36:44 10.22.2.5 0062253104 - ISU: 1, isup_cp_tone_elem_process_event, det 6, elem 1(off_cad) gets event tone_off^M
Jul 17 11:36:44 10.22.2.5 0062253105 - ISU: 1, isup_cp_tone_det_process_event, det 6, elem 1(off_cad) returned start_timer^M
Jul 17 11:36:44 10.22.2.5 0062253105 - ISU: 1, isup_cp_tone_det_process_event, det 6, elem 1(off_cad) timeout value = 225^M
Jul 17 11:36:44 10.22.2.5 0062253105 - ISU: 1, Call progress detection timer started, period = 302 ms^M
Jul 17 11:36:45 10.22.2.5 0062253257 - ISU: 1, Call progress detection timer expired^M
Jul 17 11:36:45 10.22.2.5 0062253257 - ISU: 1, isup_cp_tone_elem_process_event, det 6, elem 1(off_cad) gets event timer_exp^M
Jul 17 11:36:45 10.22.2.5 0062253257 - ISU: 1, isup_cp_tone_det_process_event, det 6, elem 1(off_cad) returned start_timer^M
Jul 17 11:36:45 10.22.2.5 0062253258 - ISU: 1, isup_cp_tone_det_process_event, det 6, elem 1(off_cad) timeout value = 275^M
Jul 17 11:36:45 10.22.2.5 0062253258 - ISU: 1, Call progress detection timer started, period = 46 ms^M
Jul 17 11:36:45 10.22.2.5 0062253281 - ISU: 1, Call progress detection timer expired^M
Jul 17 11:36:45 10.22.2.5 0062253281 - ISU: 1, isup_cp_tone_elem_process_event, det 6, elem 1(off_cad) gets event timer_exp^M
Jul 17 11:36:45 10.22.2.5 0062253281 - ISU: 1, isup_cp_tone_det_process_event, det 6, elem 1(off_cad) returned reset^M
Jul 17 11:36:45 10.22.2.5 0062253281 - ISU: 1, isup_cp_tone_det_process_event, det 6, next element = 0^M
Jul 17 11:36:45 10.22.2.5 0062253282 - ISU: 1, isup_cp_tone_elem_process_event, det 6, elem 0(on_cad) gets event init^M
Jul 17 11:36:45 10.22.2.5 0062253282 - ISU: 1, isup_cp_tone_det_process_event, det 6, elem 0(on_cad) returned start_timer^M
Jul 17 11:36:45 10.22.2.5 0062253282 - ISU: 1, isup_cp_tone_det_process_event, det 6, elem 0(on_cad) timeout value = forever^M
Jul 17 11:36:45 10.22.2.5 0062253283 - ISU: 1, Call progress detection timer period = forever, timer not started^M
Jul 18 03:21:15 10.22.2.5 0000009571 - SYSLOG: hadong, network syslog initial done^M


-------- last 5 sec before reboot
Jul 18 03:20:31 10.22.2.5 0027564163 - RTCP: 0, rtcpp_send_encrypt_eligible_pkt^M
Jul 18 03:20:31 10.22.2.5 0027564163 - PSU: *** psup_util_lookup_ccb - call ref 0006002d NOT found^M
Jul 18 03:20:31 10.22.2.5 0027564163 - PSU: *** psup_proc_smc2_data - invalid ccb - type  5^M
Jul 18 03:20:32 10.22.2.5 0027564662 - RTCP: 1, received RXTX stats^M
Jul 18 03:20:32 10.22.2.5 0027564663 - RTCP: 1, rtcpp_send_pkt, call_back: 0x0^M
Jul 18 03:20:32 10.22.2.5 0027564663 - RTCP: 1, rtcpp_send_encrypt_eligible_pkt^M
Jul 18 03:20:33 10.22.2.5 0027565083 - RTCP: 3, received RXTX stats^M
Jul 18 03:20:33 10.22.2.5 0027565083 - RTCP: 3, rtcpp_send_pkt, call_back: 0x0^M
Jul 18 03:20:33 10.22.2.5 0027565083 - RTCP: 3, rtcpp_send_encrypt_eligible_pkt^M
Jul 18 03:20:35 10.22.2.5 0027566485 - TIU: Reset ETSI FSK CID on 0^M
Jul 18 03:20:35 10.22.2.5 0027566485 - LFXO: 0, fake_in_use gets event 27^M
Jul 18 03:20:35 10.22.2.5 0027566486 - LFXO: 0, fake_in_use ==> idle^M
Jul 18 03:20:35 10.22.2.5 0027566486 - LSS: 0, voice_enable=0^M
Jul 18 03:20:35 10.22.2.5 0027566486 - SPU: 0, set coding state=0^M
Jul 18 03:20:35 10.22.2.5 0027566486 - SPU: 0, tone_gen tone=255, to_tele=1, to_net=0^M
Jul 18 03:20:35 10.22.2.5 0027566487 - Chan 0 reset silence flag and counter^M
Jul 18 03:20:35 10.22.2.5 0027566487 - CPS: 0, fake_in_use_dsp_ready gets event 0^M
Jul 18 03:20:35 10.22.2.5 0027566487 - CPS: 0, fake_in_use_dsp_ready ==> idle^M
Jul 18 03:20:35 10.22.2.5 0027566488 - SPU: 0, Net set busy=0, ccb_state=1^M
Jul 18 03:20:35 10.22.2.5 0027566488 - SPU: 0, spup_net_set_busy ccb_state=1^M
Jul 18 03:20:35 10.22.2.5 0027566488 - SPU: 0, Starting coding request coding=255^M
Jul 18 03:20:35 10.22.2.5 0027566488 - SPU: 0, coding=255, coding_state=0, p_tcid->cp_tone=255^M
Jul 18 03:20:35 10.22.2.5 0027566489 - CPS: 0, voice_enable=0^M
Jul 18 03:20:35 10.22.2.5 0027566489 - CPS: 0, idle ==> idle^M
Jul 18 03:20:35 10.22.2.5 0027566489 - SPU: 0, Net set busy=0, ccb_state=1^M
Jul 18 03:20:35 10.22.2.5 0027566489 - SPU: 0, spup_net_set_busy ccb_state=1^M
Jul 18 03:20:35 10.22.2.5 0027566490 - SPU: 0, Queue coding request coding=255^M
Jul 18 03:20:35 10.22.2.5 0027566490 - CPS: 0, voice_enable=0^M
Jul 18 03:20:35 10.22.2.5 0027566496 - TIU: Set ETSI FSK CID on 0^M
Jul 18 03:20:35 10.22.2.5 0027566496 - LFXO: 0, idle gets event 26^M
Jul 18 03:20:35 10.22.2.5 0027566496 - LSS: 0 Receive a fake ringing^M
Jul 18 03:20:35 10.22.2.5 0027566497 - LFXO: 0, idle ==> fake_in_use^M
Jul 18 03:20:35 10.22.2.5 0027566497 - LSS: 0, voice_enable=1^M
Jul 18 03:20:35 10.22.2.5 0027566497 - CPS: 0, idle gets event 28^M
Jul 18 03:20:35 10.22.2.5 0027566497 - CPS: 0 Got a fake LSS_in_use_ind^M
Jul 18 03:20:35 10.22.2.5 0027566498 - CPS: 0, idle ==> fake_port_in_use^M
Jul 18 03:20:35 10.22.2.5 0027566498 - SPU: 0, Queue coding request coding=0^M
Jul 18 03:20:35 10.22.2.5 0027566503 - CCU: 0, Tones off, direction=3^M
Jul 18 03:20:35 10.22.2.5 0027566504 - AMU: 0, Report State oper_state=2 admin_state=2 call_state=0^M
Jul 18 03:20:35 10.22.2.5 0027566504 - NMM: 0, states: oper=NORMAL, admin=NORMAL, call=IDLE^M
Jul 18 03:20:35 10.22.2.5 0027566508 - AMU: 0, Report State oper_state=2 admin_state=2 call_state=0^M
Jul 18 03:20:35 10.22.2.5 0027566508 - NMM: 0, states: oper=NORMAL, admin=NORMAL, call=IDLE^M
Jul 18 03:20:35 10.22.2.5 0027566508 - SFU: dispatch_gen_msg: msg_id =3^M
Jul 18 03:20:35 10.22.2.5 0027566508 - SFU: tsg_state_to_sfu_state - converted tsg_state=0 to sfu_state=2 ^M
Jul 18 03:20:35 10.22.2.5 0027566510 - SPU: 0, Voice band data detection ended, result = -1^M
Jul 18 03:20:35 10.22.2.5 0027566508 - SFU: call_state_update info: XMC_id=0 tsg_id.port=0 sfu_call_state=2, sfu_id=65535, apperance
= 0 ^M
Jul 18 03:20:35 10.22.2.5 0027566513 - SFU: tsg_id.sfu_id == SFU_INVALID_CALL_LEG_ID, p_call_leg 0x0^M
Jul 18 03:20:35 10.22.2.5 0027566513 - SFU: after sfu_find_call_leg_sfu_id(), p_call_leg 0x0^M
Jul 18 03:20:35 10.22.2.5 0027566514 - SFU: dispatch_gen_msg: msg_id =3^M
Jul 18 03:20:35 10.22.2.5 0027566514 - SFU: tsg_state_to_sfu_state - converted tsg_state=0 to sfu_state=2 ^M
Jul 18 03:20:35 10.22.2.5 0027566514 - SFU: call_state_update info: XMC_id=0 tsg_id.port=0 sfu_call_state=2, sfu_id=65535, apperance
= 0 ^M
Jul 18 03:20:36 10.22.2.5 0027566515 - CCU: Cannot allocate packet - tsg_get_voice_data_buf()^M
Jul 18 03:20:36 10.22.2.5 last message repeated 2 times
Jul 18 03:20:36 10.22.2.5 0027566514 - SFU: tsg_id.sfu_id == SFU_INVALID_CALL_LEG_ID, p_call_leg 0x0^M
Jul 18 03:20:36 10.22.2.5 0027566518 - SFU: after sfu_find_call_leg_sfu_id(), p_call_leg 0x0^M
Jul 18 03:20:36 10.22.2.5 0027566519 - ISU: 0, Tones off, dir=3^M
Jul 18 03:20:36 10.22.2.5 0027566519 - ISU: 0, Aborting all tones for inst(s) 0!^M
Jul 18 03:20:36 10.22.2.5 0027566519 - ISU: 0, Tones off, dir=3^M
Jul 18 03:20:36 10.22.2.5 0027566519 - ISU: 0, Aborting all tones for inst(s) 0!^M
Jul 18 03:20:36 10.22.2.5 0027566519 - ISU: 0, Call progress tone OFF^M
Jul 18 03:20:36 10.22.2.5 0027566521 - CCU: Cannot allocate packet - tsg_get_voice_data_buf()^M
Jul 18 03:20:36 10.22.2.5 0027566543 - CCU: Cannot allocate packet - tsg_get_voice_data_buf()^M
Jul 18 03:20:36 10.22.2.5 0027566544 - CCU: Cannot allocate packet - tsg_get_voice_data_buf()^M
Jul 18 03:20:36 10.22.2.5 last message repeated 2 times
Jul 18 03:21:15 10.22.2.5 0000009571 - SYSLOG: hadong, network syslog initial done^M
New Member

Re: spa400 are constantly reboot


In the configuration SPA400Configuration_060109.pdf to mexico
Cisco Employee

Re: spa400 are constantly reboot

Hi galmague1,

I received 2 emails with log information, but still need the information I requested earlier in this thread.

Please use the community-supplied subject in your email, else I may not see your email due to email filters.

Regards,

Patrick

-----------

Cisco Employee

Re: spa400 are constantly reboot

Hi galmague1,

I received 4 emails with information from you. I've forwarded the information to Escalation Engineering.

Regards,

Patrick

-----------

Cisco Employee

Re: spa400 are constantly reboot

Community update:

I've checked with Engineering and they working this issue.

Regards,

Patrick

----------

Cisco Employee

Re: spa400 are constantly reboot

Community update,

I've just heard back from Engineering. They are still working the issue.

In the interim, if you're in the market for hardware, please consider the SPA8800 which is a 4-port FXO and 4-port FXS gateway that works well with Asterisk. Here's an Application note that I wrote on deploying in an Asterisk environment: https://www.myciscocommunity.com/docs/DOC-7654

Regards,

Patrick

----------

New Member

Re: spa400 are constantly reboot

apparently removing the pending call from our provider decreased rebounding,

but continuous, at 1-2 weekly reboot, when CID receives a blank or garbage.
apparently there is an error in the CID system, because when you get a call

from a phone other carrier  different  us who do not manage

the SPA400 restart with error CID with the NEXT error

       "ASSERT failure in sfucalls.c file at line 531"

Cisco Employee

Re: spa400 are constantly reboot

New Member

Re: spa400 are constantly reboot

I tried 1.1.2.3 that was posted in the hopes that it would solve the two ring issue, as I have read in other posts and this one does not.  If it was supposed to, it didn't.  Just FYI.  If it's not on the list, please refix this.  My clients are willing to loose caller ID to get the phone to ring earlier.

Cisco Employee

Re: spa400 are constantly reboot

I've filed a bug against this so it can be better tracked: CDETS# CSCtb95987

Regards,

Patrick

-----------

Cisco Employee

Re: spa400 are constantly reboot

Hi galmague1,

How is the SPA400 behaving? Are you still experiencing reboots?

Engineering have informed me that they are unable to replicate the issues that you are experiencing. Can you provide any additional information to help them replicate the problem please?

Regards,

Patrick

----------

9368
Views
0
Helpful
18
Replies
CreatePlease to create content