Re: SPA112 Can't receive calls after a while

enkoopa11 · ‎11-07-2013

I've got two SPA112's that can't get calls after a while. Firmware is the latest, 1.3.2.

NAT keep alive is enabled, registration expiration is 180s. Things work great and then eventually they just stop, line goes dead, no incoming calls, no outgoing calls either (no dialtone).

Not sure where to go next, and I just read that 1.3.2 the logging doesn't even work?

dgrozdanovski · ‎02-27-2014

At the same time dial signal is choppy for about 5 seconds. Dialing out is working fine. All incoming calls have busy signal. Restoring backup fixes ATA behavior for hour or two. Device is registered. Restart or power off/on do not fix the issue. I have external static IP address. Tried NAT keep alive, no difference. No forum at this time provides setting that may alleviate issue.

With firmware 1.3.2 good working condition was lasting about a day or two. Upgrade to 1.3.3 made it worse.

Dan Lukes · ‎02-27-2014

Turn on syslog&debug messages and catch them. It will help with further analysis. Your's chances for usefull advice or solution is very low without it.

dgrozdanovski · ‎02-27-2014

Hi Dan,

Thank you for prompt respond. There is no button to upload text file, so here is inline:

Feb 27 15:00:01 SPA112 syslog.notice syslog-ng[130]: syslog-ng version 1.6.12 starting

Feb 27 15:00:01 SPA112 kern.notice [ 0.000000] Linux version 2.6.26.5 (menrao@Payton) (gcc version 4.1.2) #1 PREEMPT Fri Oct 25 14:06:15 CST 2013

Feb 27 15:00:01 SPA112 kern.warning [ 0.000000] CPU: ARM926EJ-S [41069265] revision 5 (ARMv5TEJ), cr=00053177

Feb 27 15:00:01 SPA112 kern.warning [ 0.000000] Machine: NXP PNX8181

Feb 27 15:00:01 SPA112 kern.warning [ 0.000000] Memory policy: ECC disabled, Data cache writeback

Feb 27 15:00:01 SPA112 kern.debug [ 0.000000] On node 0 totalpages: 7936

Feb 27 15:00:01 SPA112 kern.debug [ 0.000000] DMA zone: 62 pages used for memmap

Feb 27 15:00:01 SPA112 kern.debug [ 0.000000] DMA zone: 0 pages reserved

Feb 27 15:00:01 SPA112 kern.debug [ 0.000000] DMA zone: 7874 pages, LIFO batch:0

Feb 27 15:00:01 SPA112 kern.debug [ 0.000000] Normal zone: 0 pages used for memmap

Feb 27 15:00:01 SPA112 kern.debug [ 0.000000] Movable zone: 0 pages used for memmap

Feb 27 15:00:01 SPA112 kern.warning [ 0.000000] CPU0: D VIVT write-back cache

Feb 27 15:00:01 SPA112 kern.warning [ 0.000000] CPU0: I cache: 32768 bytes, associativity 4, 32 byte lines, 256 sets

Feb 27 15:00:01 SPA112 kern.warning [ 0.000000] CPU0: D cache: 32768 bytes, associativity 4, 32 byte lines, 256 sets

Feb 27 15:00:01 SPA112 kern.warning [17179569.184000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 7874

Feb 27 15:00:01 SPA112 kern.notice [17179569.184000] Kernel command line: console=ttyS1,115200n8 rootfstype=squashfs noalign half_image=0 verify=y Hw_Model=SPA112 Router_Mode=0

Feb 27 15:00:01 SPA112 kern.info [17179569.184000] PNX8181: Configured 66 Interrupts

Feb 27 15:00:01 SPA112 kern.warning [17179569.184000] PID hash table entries: 128 (order: 7, 512 bytes)

Feb 27 15:00:01 SPA112 kern.warning [17179569.184000] Console: colour dummy device 80x30

Feb 27 15:00:01 SPA112 kern.info [17179569.184000] Dentry cache hash table entries: 4096 (order: 2, 16384 bytes)

Feb 27 15:00:01 SPA112 kern.info [17179569.184000] Inode-cache hash table entries: 2048 (order: 1, 8192 bytes)

Feb 27 15:00:01 SPA112 kern.info [17179569.188000] Memory: 31MB = 31MB total

Feb 27 15:00:01 SPA112 kern.notice [17179569.188000] Memory: 28296KB available (2804K code, 197K data, 120K init)

Feb 27 15:00:01 SPA112 kern.debug [17179569.188000] Calibrating delay loop... 116.99 BogoMIPS (lpj=233984)

Feb 27 15:00:01 SPA112 kern.warning [17179569.268000] Mount-cache hash table entries: 512

Feb 27 15:00:01 SPA112 kern.info [17179569.268000] CPU: Testing write buffer coherency: ok

Feb 27 15:00:01 SPA112 kern.info [17179569.272000] net_namespace: 484 bytes

Feb 27 15:00:01 SPA112 kern.info [17179569.272000] NET: Registered protocol family 16

Feb 27 15:00:01 SPA112 kern.info [17179569.272000] Board: found phy at 0x03, id 0x001cc815

Feb 27 15:00:01 SPA112 kern.info [17179569.272000] Board: Vega_PNX8181_BaseStation low-cost version detected.

Feb 27 15:00:01 SPA112 kern.info [17179569.272000] clock [intc] enabled

Feb 27 15:00:01 SPA112 kern.info [17179569.272000] clock [sctu] enabled

Feb 27 15:00:01 SPA112 kern.info [17179569.272000] clock [uart1] enabled

Feb 27 15:00:01 SPA112 kern.info [17179569.272000] clock [uart2] enabled

Feb 27 15:00:01 SPA112 kern.info [17179569.272000] clock [sdi] enabled

Feb 27 15:00:01 SPA112 kern.info [17179569.272000] clock [ebi1] enabled

Feb 27 15:00:01 SPA112 kern.info [17179569.272000] clock [ebi2] enabled

Feb 27 15:00:01 SPA112 kern.info [17179569.272000] clock [gpio] enabled

Feb 27 15:00:01 SPA112 kern.notice [17179569.272000] gpio_init: Registered PNX818 GPIO device

Feb 27 15:00:01 SPA112 kern.warning [17179569.272000] Board HW MODEL : 0x3

Feb 27 15:00:01 SPA112 kern.info [17179569.272000] clock [extint] enabled

Feb 27 15:00:01 SPA112 kern.info [17179569.272000] External Interrupt Controller registered

Feb 27 15:00:01 SPA112 kern.info [17179569.288000] NET: Registered protocol family 2

Feb 27 15:00:01 SPA112 kern.info [17179569.324000] IP route cache hash table entries: 1024 (order: 0, 4096 bytes)

Feb 27 15:00:01 SPA112 kern.info [17179569.324000] TCP established hash table entries: 1024 (order: 1, 8192 bytes)

Feb 27 15:00:01 SPA112 kern.info [17179569.324000] TCP bind hash table entries: 1024 (order: 0, 4096 bytes)

Feb 27 15:00:01 SPA112 kern.info [17179569.324000] TCP: Hash tables configured (established 1024 bind 1024)

Feb 27 15:00:01 SPA112 kern.info [17179569.324000] TCP reno registered

Feb 27 15:00:01 SPA112 kern.info [17179569.336000] NET: Registered protocol family 1

Feb 27 15:00:01 SPA112 kern.info [17179569.336000] clock [dmau] enabled

Feb 27 15:00:01 SPA112 kern.info [17179569.336000] probe succeded

Feb 27 15:00:01 SPA112 kern.info [17179569.336000] clock [iic] enabled

Feb 27 15:00:01 SPA112 kern.info [17179569.340000] squashfs: version 3.4 (2008/08/26) Phillip Lougher

Feb 27 15:00:01 SPA112 kern.warning [17179569.340000] squashfs: LZMA suppport for slax.org by jro

Feb 27 15:00:01 SPA112 kern.info [17179569.344000] msgmni has been set to 55

Feb 27 15:00:01 SPA112 kern.info [17179569.344000] io scheduler noop registered (default)

Feb 27 15:00:01 SPA112 kern.info [17179569.352000] HDLC line discipline: version $Revision: 1.1.1.1 $, maxframe=4096

Feb 27 15:00:01 SPA112 kern.info [17179569.352000] N_HDLC line discipline registered.

Feb 27 15:00:01 SPA112 kern.info [17179569.352000] Non-volatile memory driver v1.2

Feb 27 15:00:01 SPA112 kern.info [17179569.352000] Serial: 8250/16550 driver $Revision: 1.1.1.1 $ 2 ports, IRQ sharing disabled

Feb 27 15:00:01 SPA112 kern.info [17179569.352000] serial8250.0: ttyS0 at MMIO 0xc2004000 (irq = 24) is a 16550A

Feb 27 15:00:01 SPA112 kern.info [17179569.352000] serial8250.0: ttyS1 at MMIO 0xc2005000 (irq = 23) is a TI16750

Feb 27 15:00:01 SPA112 kern.info [17179569.352000] console [ttyS1] enabled

Feb 27 15:00:01 SPA112 kern.info [17179569.356000] DCC: JTAG1 Serial emulation driver driver $Revision: 1.1.1.1 $

Feb 27 15:00:01 SPA112 kern.info [17179569.360000] ttyJ0 at MMIO 0x12345678 (irq = 0) is a DCC

Feb 27 15:00:01 SPA112 kern.info [17179569.364000] brd: module loaded

Feb 27 15:00:01 SPA112 kern.info [17179569.368000] PPP generic driver version 2.4.2

Feb 27 15:00:01 SPA112 kern.info [17179569.376000] PPP MPPE Compression module registered

Feb 27 15:00:01 SPA112 kern.info [17179569.380000] NET: Registered protocol family 24

Feb 27 15:00:01 SPA112 kern.info [17179569.384000] PPPoL2TP kernel driver, V1.0

Feb 27 15:00:01 SPA112 kern.warning [17179569.388000] [ip3912] : Bridge Mode...

Feb 27 15:00:01 SPA112 kern.info [17179569.392000] clock [etn1] enabled

Feb 27 15:00:01 SPA112 kern.info [17179569.400000] ip3912_mii_bus: probed

Feb 27 15:00:01 SPA112 kern.info [17179569.404000] eth0: IP3912 at 0xc1600000 using 0:03 phy

Feb 27 15:00:01 SPA112 kern.info [17179569.412000] NFTL driver: nftlcore.c $Revision: 1.1.1.1 $, nftlmount.c $Revision: 1.1.1.1 $

Feb 27 15:00:01 SPA112 kern.notice [17179569.416000] physmap platform flash device: 02000000 at 80000000

Feb 27 15:00:01 SPA112 kern.debug [17179569.420000] CFI: Found no physmap-flash.0 device at location zero

Feb 27 15:00:01 SPA112 kern.err [17179569.424000] physmap-flash physmap-flash.0: map_probe failed

Feb 27 15:00:01 SPA112 kern.info [17179569.432000] NAND device: Manufacturer ID: 0xad, Chip ID: 0x75 (Hynix NAND 32MiB 3,3V 8-bit)

Feb 27 15:00:01 SPA112 kern.debug [17179569.436000] Bad block table found at page 65504, version 0x01

Feb 27 15:00:01 SPA112 kern.debug [17179569.436000] Bad block table found at page 65472, version 0x01

Feb 27 15:00:01 SPA112 kern.warning [17179569.436000] Using Full Image\'s RootFS

Feb 27 15:00:01 SPA112 kern.warning [17179569.440000] Using static partition definition

Feb 27 15:00:01 SPA112 kern.warning [17179569.444000] !!! do adler32 checksum !!!

Feb 27 15:00:01 SPA112 kern.warning [17179571.224000] File system image checksum OK

Feb 27 15:00:01 SPA112 kern.notice [17179571.228000] Creating 11 MTD partitions on \"gen_nand\":

Feb 27 15:00:01 SPA112 kern.notice [17179571.228000] 0x00000000-0x00060000 : \"u-boot\"

Feb 27 15:00:01 SPA112 kern.notice [17179571.232000] 0x00060000-0x00080000 : \"u-bootenv\"

Feb 27 15:00:01 SPA112 kern.notice [17179571.236000] 0x00080000-0x01460000 : \"ROMIMAGE\"

Feb 27 15:00:01 SPA112 kern.notice [17179571.240000] 0x01460000-0x01b60000 : \"HALFIMAGE\"

Feb 27 15:00:01 SPA112 kern.notice [17179571.244000] 0x00200000-0x01460000 : \"LINUX_ROOTFS\"

Feb 27 15:00:01 SPA112 kern.notice [17179571.248000] 0x01b60000-0x01d60000 : \"HS_FW\"

Feb 27 15:00:01 SPA112 kern.notice [17179571.252000] 0x01d60000-0x01e60000 : \"FPAR\"

Feb 27 15:00:01 SPA112 kern.notice [17179571.256000] 0x01e60000-0x01ee0000 : \"CISCO\"

Feb 27 15:00:01 SPA112 kern.notice [17179571.260000] 0x01ee0000-0x01f00000 : \"EEPROM\"

Feb 27 15:00:01 SPA112 kern.notice [17179571.264000] 0x01f00000-0x01f80000 : \"NVRAM\"

Feb 27 15:00:01 SPA112 kern.notice [17179571.272000] 0x01f80000-0x02000000 : \"CA_DATA\"

Feb 27 15:00:01 SPA112 kern.info [17179571.276000] clock [spi1] enabled

Feb 27 15:00:01 SPA112 kern.info [17179571.284000] spi-pnx8181 spi-pnx8181: probe succeded

Feb 27 15:00:01 SPA112 kern.info [17179571.288000] i2c /dev entries driver

Feb 27 15:00:01 SPA112 kern.err [17179571.296000] ksz8873 0-005f: failed with status -1

Feb 27 15:00:01 SPA112 kern.warning [17179571.300000] ksz8873: probe of 0-005f failed with error -1

Feb 27 15:00:01 SPA112 kern.warning [17179571.304000] PNX8181 watchdog timer: timer margin 16 sec

Feb 27 15:00:01 SPA112 kern.info [17179571.308000] Registered led device: led1

Feb 27 15:00:01 SPA112 kern.info [17179571.312000] Registered led device: led2

Feb 27 15:00:01 SPA112 kern.debug [17179571.316000] cordless: SCRAM mapped to 0xd0000000

Feb 27 15:00:01 SPA112 kern.info [17179571.316000] cordless: character device initialized (major=254)

Feb 27 15:00:01 SPA112 kern.info [17179571.320000] coma-debug: coma debug support enabled

Feb 27 15:00:01 SPA112 kern.warning [17179571.324000] GACT probability on

Feb 27 15:00:01 SPA112 kern.warning [17179571.328000] Mirror/redirect action on

Feb 27 15:00:01 SPA112 kern.warning [17179571.332000] u32 classifier

Feb 27 15:00:01 SPA112 kern.warning [17179571.336000] Performance counters on

Feb 27 15:00:01 SPA112 kern.warning [17179571.340000] input device check on

Feb 27 15:00:01 SPA112 kern.warning [17179571.344000] Actions configured

Feb 27 15:00:01 SPA112 kern.warning [17179571.348000] Netfilter messages via NETLINK v0.30.

Feb 27 15:00:01 SPA112 kern.warning [17179571.352000] nf_conntrack version 0.5.0 (1024 buckets, 4096 max)

Feb 27 15:00:01 SPA112 kern.warning [17179571.364000] ipt_time loading

Feb 27 15:00:01 SPA112 kern.info [17179571.368000] TCP cubic registered

Feb 27 15:00:01 SPA112 kern.info [17179571.372000] NET: Registered protocol family 17

Feb 27 15:00:01 SPA112 kern.notice [17179571.376000] Bridge firewalling registered

Feb 27 15:00:01 SPA112 kern.info [17179571.380000] Ebtables v2.0 registered

Feb 27 15:00:01 SPA112 kern.info [17179571.388000] RPC: Registered udp transport module.

Feb 27 15:00:01 SPA112 kern.info [17179571.392000] RPC: Registered tcp transport module.

Feb 27 15:00:01 SPA112 kern.info [17179571.396000] 802.1Q VLAN Support v1.8 Ben Greear <greearb@candelatech.com>

Feb 27 15:00:01 SPA112 kern.info [17179571.400000] All bugs added by David S. Miller <davem@redhat.com>

Feb 27 15:00:01 SPA112 kern.info [17179571.404000] LINUX_ROOTFS is 4

Feb 27 15:00:01 SPA112 kern.warning [17179571.416000] VFS: Mounted root (squashfs filesystem) readonly.

Feb 27 15:00:01 SPA112 kern.info [17179571.424000] Freeing init memory: 120K

Feb 27 15:00:01 SPA112 kern.info [17179572.276000] eth0: Link down

Feb 27 15:00:01 SPA112 kern.info [17179573.276000] ip3912: eth0 up, speed is 100 Mbps, Full Duplex.

Feb 27 15:00:01 SPA112 kern.info [17179575.444000] coma-config: netlink interface registered

Feb 27 15:00:01 SPA112 kern.info [17179575.552000] coma-cpi: netlink interface registered

Feb 27 15:00:01 SPA112 kern.info [17179575.600000] coma-ss7: netlink interface registered

Feb 27 15:00:01 SPA112 kern.info [17179575.656000] coma-voice: character device initialized (major=253)

Feb 27 15:00:01 SPA112 kern.info [17179575.700000] coma-userch: netlink interface registered

Feb 27 15:00:01 SPA112 kern.info [17179575.804000] coma-dsr: netlink interface registered

Feb 27 15:00:01 SPA112 kern.warning [17179575.836000] ***** LED_DRV init *****

Feb 27 15:00:01 SPA112 kern.warning [17179575.840000] ***** LED_DRV end *****

Feb 27 15:00:01 SPA112 kern.warning [17179575.868000] *** sys event driver initialized ***

Feb 27 15:00:01 SPA112 kern.err [17179578.940000] br0: Dropping NETIF_F_UFO since no NETIF_F_HW_CSUM feature.

Feb 27 15:00:01 SPA112 kern.info [17179580.548000] device eth0 entered promiscuous mode

Feb 27 15:00:01 SPA112 kern.info [17179580.548000] br0: port 1(eth0) entering learning state

Feb 27 15:00:01 SPA112 kern.debug [17179580.556000] sysevt_comm_sendto: (52, rc)=>

Feb 27 15:00:01 SPA112 kern.debug [17179580.568000] sysevt_comm_sendto: (52, rc)=>

Feb 27 15:00:01 SPA112 kern.info [17179582.548000] br0: topology change detected, propagating

Feb 27 15:00:01 SPA112 kern.info [17179582.548000] br0: port 1(eth0) entering forwarding state

Feb 27 15:00:02 SPA112 daemon.info system[141]: httpd server started at port 80

Feb 27 15:00:02 SPA112 daemon.info dnsmasq[148]: started, version 1.10 cachesize 150

Feb 27 15:00:02 SPA112 daemon.err dnsmasq[148]: failed to load names from /etc/hosts: No such file or directory

Feb 27 15:00:02 SPA112 daemon.debug dnsmasq[148]: reading /tmp/dns_resolv.conf

Feb 27 15:00:02 SPA112 daemon.info dnsmasq[148]: using nameserver 1.1.1.1

Feb 27 15:00:02 SPA112 daemon.notice system[1]: Ethernet WAN br0 link up

Feb 27 15:00:03 SPA112 daemon.notice system[1]: Start WAN br0 DHCP connection

Feb 27 15:00:03 SPA112 kern.debug [17179584.740000] sysevt_comm_sendto: (25, rc)=>

Feb 27 15:00:03 SPA112 kern.debug [17179584.964000] sysevt_comm_sendto: (16, rc)=>

Feb 27 15:00:07 SPA112 kern.debug [17179588.552000] sysevt_comm_sendto: (97, rc)=>

Feb 27 15:00:07 SPA112 daemon.notice system[1]: WAN br0 connected

Feb 27 15:00:07 SPA112 daemon.notice system[1]: Link name=br0

Feb 27 15:00:07 SPA112 daemon.notice system[1]: IP address=192.168.1.118

Feb 27 15:00:07 SPA112 daemon.notice system[1]: Netmask=255.255.255.0

Feb 27 15:00:07 SPA112 daemon.notice system[1]: Gateway=192.168.1.1

Feb 27 15:00:07 SPA112 daemon.notice system[1]: hostname=

Feb 27 15:00:07 SPA112 daemon.notice system[1]: domain=

Feb 27 15:00:07 SPA112 daemon.notice system[1]: dns_0=67.55.0.11

Feb 27 15:00:07 SPA112 kern.debug [17179588.624000] sysevt_comm_sendto: (16, rc)=>

Feb 27 15:00:07 SPA112 daemon.notice system[1]: dns_1=66.49.220.95

Feb 27 15:00:07 SPA112 kern.debug [17179588.724000] sysevt_comm_sendto: (480, rc)=>

Feb 27 15:00:07 SPA112 kern.debug [17179588.736000] sysevt_comm_sendto: (480, rc)=>

Feb 27 15:00:07 SPA112 kern.debug [17179588.780000] sysevt_comm_sendto: (25, rc)=>

Feb 27 15:00:07 SPA112 daemon.err dnsmasq[148]: failed to load names from /etc/hosts: No such file or directory

Feb 27 15:00:07 SPA112 daemon.debug system[1]: leave reload_dnsmasq_conf_default

Feb 27 14:59:32 SPA112 daemon.notice system[116]: NTP update successfully, Year:2014,Month:2,Day:27,Hour:14,Min:59,Sec:32

Feb 27 14:59:32 SPA112 kern.debug [17179589.312000] sysevt_event_sendto: =>(0, B5817EF8, ledapp)

Feb 27 14:59:32 SPA112 kern.debug [17179589.316000] sysevt_event_sendto: =>type = 1048663

Feb 27 14:59:32 SPA112 kern.debug [17179589.316000] sysevt_event_sendto: =>size = 0

Feb 27 14:59:32 SPA112 kern.debug [17179589.316000] sysevt_comm_sendto: (12, ledapp)=>

Feb 27 14:59:48 SPA112 kern.info [17179605.188000] cordless: loading synergy-2013-10-11

Feb 27 14:59:48 SPA112 kern.err [17179605.216000] Created coma thread for processing coma control message

Feb 27 14:59:48 SPA112 kern.info [17179605.232000] cordless: init successful

Feb 27 14:59:50 SPA112 user.notice msgswitchd: MSGSWITCH fd_rtp fifo created 7

Feb 27 14:59:50 SPA112 user.notice msgswitchd: MSGSWITCH fd_ch fifo created 9

Feb 27 14:59:50 SPA112 user.notice msgswitchd: MSGSWITCH fd_gmep fifo created 10

Feb 27 15:00:04 SPA112 user.notice vsock: gch_ListenStart: Started Read thread

Feb 27 15:00:13 SPA112 user.notice sprvoip: cmd 5, EP 2, ParameterType 22, ParameterValue 1

Feb 27 15:00:13 SPA112 user.notice sprvoip: cmd - 5, response 8

Feb 27 15:00:13 SPA112 user.notice sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 60

Feb 27 15:00:13 SPA112 user.notice sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 70

Feb 27 15:00:13 SPA112 user.notice sprvoip: cmd - 5, response 8

Feb 27 15:00:13 SPA112 user.notice sprvoip: cmd 5, EP 1, ParameterType 22, ParameterValue 1

Feb 27 15:00:13 SPA112 user.notice sprvoip: cmd - 5, response 8

Feb 27 15:00:13 SPA112 user.notice sprvoip: cmd 5, EP 1, ParameterType 27, ParameterValue 60

Feb 27 15:00:13 SPA112 user.notice sprvoip: cmd 5, EP 1, ParameterType 26, ParameterValue 70

Feb 27 15:00:13 SPA112 user.notice sprvoip: cmd - 5, response 8

Feb 27 15:00:16 SPA112 user.notice sprvoip: cmd - 18, response 23

Feb 27 15:00:17 SPA112 user.notice sprvoip: cmd - 18, response 49

Feb 27 15:04:29 SPA112 daemon.info system[116]: MemTotal: 28416 kB

Feb 27 15:04:30 SPA112 daemon.info system[116]: MemFree: 7016 kB

Feb 27 15:08:59 SPA112 user.notice sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 20

Feb 27 15:08:59 SPA112 user.notice sprvoip: cmd - 5, response 8

Feb 27 15:08:59 SPA112 user.notice sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 30

Feb 27 15:08:59 SPA112 user.notice sprvoip: cmd - 5, response 8

Feb 27 15:08:59 SPA112 user.notice sprvoip: cmd 2

Feb 27 15:08:59 SPA112 user.notice sprvoip: Seq Num 11

Feb 27 15:08:59 SPA112 user.notice sprvoip: cmd - 2, response 2

Feb 27 15:08:59 SPA112 user.notice sprvoip: cmd 10, EP 2, Node ID 0

Feb 27 15:08:59 SPA112 user.notice sprvoip: cmd - 10, response 10

Feb 27 15:08:59 SPA112 user.notice sprvoip: cmd 14, NodeId 0

Feb 27 15:08:59 SPA112 user.notice sprvoip: cmd - 14, response 18

Feb 27 15:09:02 SPA112 user.notice sprvoip: cmd 16, NodeId 2

Feb 27 15:09:02 SPA112 user.notice sprvoip: cmd - 16, response 20

Feb 27 15:09:02 SPA112 user.notice sprvoip: cmd 14, NodeId 0

Feb 27 15:09:02 SPA112 user.notice sprvoip: cmd - 14, response 18

Feb 27 15:09:02 SPA112 user.notice sprvoip: cmd 12, NodeId 0

Feb 27 15:09:02 SPA112 user.notice sprvoip: cmd - 12, response 14

Feb 27 15:09:03 SPA112 user.notice sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 20

Feb 27 15:09:03 SPA112 user.notice sprvoip: cmd - 5, response 8

Feb 27 15:09:03 SPA112 user.notice sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 30

Feb 27 15:09:03 SPA112 user.notice sprvoip: cmd - 5, response 8

Feb 27 15:09:03 SPA112 user.notice sprvoip: cmd 2

Feb 27 15:09:03 SPA112 user.notice sprvoip: Seq Num 19

Feb 27 15:09:03 SPA112 user.notice sprvoip: cmd - 2, response 2

Feb 27 15:09:03 SPA112 user.notice sprvoip: cmd 10, EP 2, Node ID 0

Feb 27 15:09:03 SPA112 user.notice sprvoip: cmd - 10, response 10

Feb 27 15:09:03 SPA112 user.notice sprvoip: cmd 14, NodeId 0

Feb 27 15:09:03 SPA112 user.notice sprvoip: cmd - 14, response 18

Feb 27 15:09:07 SPA112 user.notice sprvoip: cmd 16, NodeId 2

Feb 27 15:09:07 SPA112 user.notice sprvoip: cmd - 16, response 20

Feb 27 15:09:07 SPA112 user.notice sprvoip: cmd 14, NodeId 0

Feb 27 15:09:07 SPA112 user.notice sprvoip: cmd - 14, response 18

Feb 27 15:09:07 SPA112 user.notice sprvoip: cmd 12, NodeId 0

Feb 27 15:09:07 SPA112 user.notice sprvoip: cmd - 12, response 14

Feb 27 15:09:08 SPA112 user.notice sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 20

Feb 27 15:09:08 SPA112 user.notice sprvoip: cmd - 5, response 8

Feb 27 15:09:08 SPA112 user.notice sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 30

Feb 27 15:09:08 SPA112 user.notice sprvoip: cmd - 5, response 8

Feb 27 15:09:08 SPA112 user.notice sprvoip: cmd 2

Feb 27 15:09:08 SPA112 user.notice sprvoip: Seq Num 27

Feb 27 15:09:08 SPA112 user.notice sprvoip: cmd - 2, response 2

Feb 27 15:09:08 SPA112 user.notice sprvoip: cmd 10, EP 2, Node ID 0

Feb 27 15:09:08 SPA112 user.notice sprvoip: cmd - 10, response 10

Feb 27 15:09:08 SPA112 user.notice sprvoip: cmd 14, NodeId 0

Feb 27 15:09:08 SPA112 user.notice sprvoip: cmd - 14, response 18

Feb 27 15:09:12 SPA112 user.notice sprvoip: cmd 16, NodeId 2

Feb 27 15:09:12 SPA112 user.notice sprvoip: cmd - 16, response 20

Feb 27 15:09:12 SPA112 user.notice sprvoip: cmd 14, NodeId 0

Feb 27 15:09:12 SPA112 user.notice sprvoip: cmd - 14, response 18

Feb 27 15:09:12 SPA112 user.notice sprvoip: cmd 12, NodeId 0

Feb 27 15:09:12 SPA112 user.notice sprvoip: cmd - 12, response 14

Feb 27 15:09:35 SPA112 daemon.info system[116]: MemTotal: 28416 kB

Feb 27 15:09:36 SPA112 daemon.info system[116]: MemFree: 6856 kB

Feb 27 15:10:01 SPA112 syslog.notice syslog-ng[130]: STATS: dropped 0

Feb 27 15:10:18 SPA112 user.notice sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 20

Feb 27 15:10:18 SPA112 user.notice sprvoip: cmd - 5, response 8

Feb 27 15:10:18 SPA112 user.notice sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 30

Feb 27 15:10:18 SPA112 user.notice sprvoip: cmd - 5, response 8

Feb 27 15:10:18 SPA112 user.notice sprvoip: cmd 2

Feb 27 15:10:18 SPA112 user.notice sprvoip: Seq Num 35

Feb 27 15:10:18 SPA112 user.notice sprvoip: cmd - 2, response 2

Feb 27 15:10:18 SPA112 user.notice sprvoip: cmd 10, EP 2, Node ID 0

Feb 27 15:10:18 SPA112 user.notice sprvoip: cmd - 10, response 10

Feb 27 15:10:18 SPA112 user.notice sprvoip: cmd 14, NodeId 0

Feb 27 15:10:18 SPA112 user.notice sprvoip: cmd - 14, response 18

Feb 27 15:10:21 SPA112 user.notice sprvoip: cmd 16, NodeId 2

Feb 27 15:10:21 SPA112 user.notice sprvoip: cmd - 16, response 20

Feb 27 15:10:21 SPA112 user.notice sprvoip: cmd 14, NodeId 0

Feb 27 15:10:21 SPA112 user.notice sprvoip: cmd - 14, response 18

Feb 27 15:10:21 SPA112 user.notice sprvoip: cmd 12, NodeId 0

Feb 27 15:10:21 SPA112 user.notice sprvoip: cmd - 12, response 14

When local logging is used, fails to work even when reloaded configuration. My syslog server does not have option to export logs.

Hope this will help to put some light on the issue.

Thank you in advance.

Dan

Dan Lukes · ‎02-27-2014

Unfortunatelly, the part of log you attached is from device boot. It contain no information related to rejected incomming call so it has no value for the purpose of analysis of your problem.

Local logging is known not to save all messages. If your current syslog server can't save messages then install another syslog server or catch messages by a generic packet catcher like Wireshark ...

Debug and syslog Messages from the SPA3xx, SPA5xxG, SPA9xx, & WIP310 IP Phones

Using the slogsrv.exe Utility

Installing and Using Wireshark for Capturing Network Traffic

dgrozdanovski · ‎02-27-2014

Hi Dan,

New logs will be available as soon as ATA fails. At the moment is working correctly. New syslog is configured and collects logs at all times-debug level.

Regards,

Dan

dgrozdanovski · ‎02-27-2014

Here it is. Did not take too long to fail.

Feb 27 12:46:01 192.168.1.118 syslog-ng[345]: syslog-ng version 1.6.12 starting
Feb 27 12:46:09 192.168.1.118 sprvoip: cmd 2
Feb 27 12:46:09 192.168.1.118 sprvoip: Seq Num 49
Feb 27 12:46:09 192.168.1.118 sprvoip: cmd - 2, response 2
Feb 27 12:46:09 192.168.1.118 sprvoip: cmd 10, EP 2, Node ID 0
Feb 27 12:46:09 192.168.1.118 sprvoip: cmd - 10, response 10
Feb 27 12:46:09 192.168.1.118 sprvoip: cmd 14, NodeId 0
Feb 27 12:46:09 192.168.1.118 sprvoip: cmd - 14, response 18
Feb 27 12:46:10 192.168.1.118 sprvoip: cmd 10, EP 3, Node ID 0
Feb 27 12:46:10 192.168.1.118 sprvoip: cmd - 10, response 10
Feb 27 12:46:10 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 22, ParameterValue 1
Feb 27 12:46:10 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 12:46:10 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 60
Feb 27 12:46:10 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 12:46:10 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 70
Feb 27 12:46:10 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 12:46:10 192.168.1.118 sprvoip: cmd - 23, response 38
Feb 27 12:46:10 192.168.1.118 sprvoip: cmd - 20, response 34
Feb 27 12:46:12 192.168.1.118 sprvoip: cmd - 18, response 23
Feb 27 12:46:12 192.168.1.118 sprvoip: cmd - 18, response 49
Feb 27 12:46:16 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 20
Feb 27 12:46:16 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 12:46:16 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 30
Feb 27 12:46:16 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 12:46:26 192.168.1.118 sprvoip: cmd 16, NodeId 2
Feb 27 12:46:26 192.168.1.118 sprvoip: cmd - 16, response 20
Feb 27 12:46:26 192.168.1.118 sprvoip: cmd 14, NodeId 0
Feb 27 12:46:26 192.168.1.118 sprvoip: cmd - 14, response 18
Feb 27 12:46:26 192.168.1.118 sprvoip: cmd 12, NodeId 0
Feb 27 12:46:26 192.168.1.118 sprvoip: cmd - 12, response 14
Feb 27 12:46:26 192.168.1.118 msgswitchd[219]:   MSGSWD RTCP Reqt len 12 Data 2,0,5,211
Feb 27 12:46:26 192.168.1.118 [17179605.804000] voice_release, chan: 0
Feb 27 12:46:32 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 20
Feb 27 12:46:32 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 12:46:32 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 30
Feb 27 12:46:32 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 12:46:32 192.168.1.118 sprvoip: cmd 2
Feb 27 12:46:32 192.168.1.118 sprvoip: Seq Num 66
Feb 27 12:46:32 192.168.1.118 sprvoip: cmd - 2, response 2
Feb 27 12:46:32 192.168.1.118 sprvoip: cmd 10, EP 2, Node ID 0
Feb 27 12:46:32 192.168.1.118 sprvoip: cmd - 10, response 10
Feb 27 12:46:32 192.168.1.118 sprvoip: cmd 14, NodeId 0
Feb 27 12:46:32 192.168.1.118 sprvoip: cmd - 14, response 18
Feb 27 12:46:40 192.168.1.118 sprvoip: cmd 16, NodeId 2
Feb 27 12:46:40 192.168.1.118 sprvoip: cmd - 16, response 20
Feb 27 12:46:40 192.168.1.118 sprvoip: cmd 14, NodeId 0
Feb 27 12:46:40 192.168.1.118 sprvoip: cmd - 14, response 18
Feb 27 12:46:40 192.168.1.118 sprvoip: cmd 12, NodeId 0
Feb 27 12:46:40 192.168.1.118 sprvoip: cmd - 12, response 14
Feb 27 12:47:06 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 20
Feb 27 12:47:06 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 12:47:06 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 30
Feb 27 12:47:06 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 12:47:06 192.168.1.118 sprvoip: cmd 2
Feb 27 12:47:06 192.168.1.118 sprvoip: Seq Num 74
Feb 27 12:47:06 192.168.1.118 sprvoip: cmd - 2, response 2
Feb 27 12:47:06 192.168.1.118 sprvoip: cmd 10, EP 2, Node ID 0
Feb 27 12:47:06 192.168.1.118 sprvoip: cmd - 10, response 10
Feb 27 12:47:06 192.168.1.118 sprvoip: cmd 14, NodeId 0
Feb 27 12:47:06 192.168.1.118 sprvoip: cmd - 14, response 18
Feb 27 12:47:09 192.168.1.118 sprvoip: cmd - 14, response 42
Feb 27 12:47:09 192.168.1.118 sprvoip: cmd - 14, response 43
Feb 27 12:47:09 192.168.1.118 sprvoip: cmd - 14, response 42
Feb 27 12:47:09 192.168.1.118 sprvoip: cmd - 14, response 43
Feb 27 12:47:09 192.168.1.118 sprvoip: cmd - 14, response 42
Feb 27 12:47:09 192.168.1.118 sprvoip: cmd - 14, response 43
Feb 27 12:47:09 192.168.1.118 sprvoip: cmd - 14, response 42
Feb 27 12:47:09 192.168.1.118 sprvoip: cmd - 14, response 43
Feb 27 12:47:09 192.168.1.118 sprvoip: cmd - 14, response 42
Feb 27 12:47:09 192.168.1.118 sprvoip: cmd - 14, response 43
Feb 27 12:47:10 192.168.1.118 sprvoip: cmd - 14, response 42
Feb 27 12:47:10 192.168.1.118 sprvoip: cmd - 14, response 43
Feb 27 12:47:10 192.168.1.118 sprvoip: cmd - 14, response 42
Feb 27 12:47:10 192.168.1.118 sprvoip: cmd - 14, response 43
Feb 27 12:47:10 192.168.1.118 sprvoip: cmd - 14, response 42
Feb 27 12:47:10 192.168.1.118 sprvoip: cmd - 14, response 43
Feb 27 12:47:10 192.168.1.118 sprvoip: cmd - 14, response 42
Feb 27 12:47:10 192.168.1.118 sprvoip: cmd - 14, response 43
Feb 27 12:47:10 192.168.1.118 sprvoip: cmd - 14, response 42
Feb 27 12:47:10 192.168.1.118 sprvoip: cmd - 14, response 43
Feb 27 12:47:11 192.168.1.118 sprvoip: cmd 10, EP 3, Node ID 0
Feb 27 12:47:11 192.168.1.118 sprvoip: cmd - 10, response 10
Feb 27 12:47:11 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 22, ParameterValue 1
Feb 27 12:47:11 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 12:47:11 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 60
Feb 27 12:47:11 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 12:47:11 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 70
Feb 27 12:47:11 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 12:47:11 192.168.1.118 sprvoip: cmd - 20, response 34
Feb 27 12:47:14 192.168.1.118 sprvoip: cmd 10, EP 3, Node ID 0
Feb 27 12:47:14 192.168.1.118 sprvoip: !!! Response (11) != CH_EP_CONNECT_ACK !!!
Feb 27 12:47:14 192.168.1.118 sprvoip: cmd - 10, response 11
Feb 27 12:47:14 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 22, ParameterValue 1
Feb 27 12:47:14 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 12:47:14 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 60
Feb 27 12:47:14 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 12:47:14 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 70
Feb 27 12:47:14 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 12:47:14 192.168.1.118 sprvoip: cmd - 20, response 34
Feb 27 12:47:16 192.168.1.118 sprvoip: cmd 10, EP 3, Node ID 0
Feb 27 12:47:16 192.168.1.118 sprvoip: !!! Response (11) != CH_EP_CONNECT_ACK !!!
Feb 27 12:47:16 192.168.1.118 sprvoip: cmd - 10, response 11
Feb 27 12:47:16 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 22, ParameterValue 1
Feb 27 12:47:16 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 12:47:16 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 60
Feb 27 12:47:16 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 12:47:16 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 70
Feb 27 12:47:16 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 12:47:16 192.168.1.118 sprvoip: cmd - 20, response 34
Feb 27 12:47:20 192.168.1.118 sprvoip: cmd - 20, response 42
Feb 27 12:47:20 192.168.1.118 sprvoip: cmd - 20, response 43
Feb 27 12:47:20 192.168.1.118 sprvoip: cmd - 20, response 42
Feb 27 12:47:20 192.168.1.118 sprvoip: cmd - 20, response 43
Feb 27 12:47:21 192.168.1.118 sprvoip: cmd - 20, response 42
Feb 27 12:47:21 192.168.1.118 sprvoip: cmd - 20, response 43
Feb 27 12:47:21 192.168.1.118 sprvoip: cmd - 20, response 42
Feb 27 12:47:21 192.168.1.118 sprvoip: cmd - 20, response 43
Feb 27 12:48:28 192.168.1.118 system[116]: MemTotal: 28416 kB
Feb 27 12:48:30 192.168.1.118 system[116]: MemFree: 10156 kB
Feb 27 12:53:33 192.168.1.118 system[116]: MemTotal: 28416 kB
Feb 27 12:53:35 192.168.1.118 system[116]: MemFree: 10172 kB
Feb 27 12:54:43 192.168.1.118 msgswitchd[219]:   MSGSWD RTCP Reqt len 12 Data 2,1093436416,255,211
Feb 27 12:54:43 192.168.1.118 msgswitchd[219]:   MSGSWD RTCP Reqt len 12 Data 2,0,3882872,211
Feb 27 12:54:43 192.168.1.118 [17180101.648000] voice_release, chan: 0
Feb 27 12:54:43 192.168.1.118 sprvoip: cmd 11, EP 3
Feb 27 12:54:43 192.168.1.118 sprvoip: cmd - 11, response 12
Feb 27 12:54:43 192.168.1.118 sprvoip: cmd 16, NodeId 2
Feb 27 12:54:43 192.168.1.118 sprvoip: cmd - 16, response 20
Feb 27 12:54:43 192.168.1.118 sprvoip: cmd 14, NodeId 0
Feb 27 12:54:43 192.168.1.118 sprvoip: cmd - 14, response 18
Feb 27 12:54:43 192.168.1.118 sprvoip: cmd 12, NodeId 0
Feb 27 12:54:43 192.168.1.118 sprvoip: cmd - 12, response 14
Feb 27 12:54:45 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 20
Feb 27 12:54:45 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 12:54:45 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 30
Feb 27 12:54:45 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 12:54:45 192.168.1.118 sprvoip: cmd 2
Feb 27 12:54:45 192.168.1.118 sprvoip: Seq Num 98
Feb 27 12:54:45 192.168.1.118 sprvoip: cmd - 2, response 2
Feb 27 12:54:45 192.168.1.118 sprvoip: cmd 10, EP 2, Node ID 0
Feb 27 12:54:45 192.168.1.118 sprvoip: cmd - 10, response 10
Feb 27 12:54:45 192.168.1.118 sprvoip: cmd 14, NodeId 0
Feb 27 12:54:45 192.168.1.118 sprvoip: cmd - 14, response 18
Feb 27 12:54:47 192.168.1.118 sprvoip: cmd 16, NodeId 2
Feb 27 12:54:47 192.168.1.118 sprvoip: cmd - 16, response 20
Feb 27 12:54:47 192.168.1.118 sprvoip: cmd 14, NodeId 0
Feb 27 12:54:47 192.168.1.118 sprvoip: cmd - 14, response 18
Feb 27 12:54:47 192.168.1.118 sprvoip: cmd 12, NodeId 0
Feb 27 12:54:47 192.168.1.118 sprvoip: cmd - 12, response 14
Feb 27 12:56:01 192.168.1.118 syslog-ng[345]: STATS: dropped 0
Feb 27 12:58:38 192.168.1.118 system[116]: MemTotal: 28416 kB
Feb 27 12:58:39 192.168.1.118 system[116]: MemFree: 10152 kB
Feb 27 13:03:42 192.168.1.118 system[116]: MemTotal: 28416 kB
Feb 27 13:03:44 192.168.1.118 system[116]: MemFree: 10124 kB
Feb 27 13:06:01 192.168.1.118 syslog-ng[345]: STATS: dropped 0
Feb 27 13:08:47 192.168.1.118 system[116]: MemTotal: 28416 kB
Feb 27 13:08:48 192.168.1.118 system[116]: MemFree: 10100 kB
Feb 27 13:13:51 192.168.1.118 system[116]: MemTotal: 28416 kB
Feb 27 13:13:52 192.168.1.118 system[116]: MemFree: 10092 kB
Feb 27 13:16:02 192.168.1.118 syslog-ng[345]: STATS: dropped 0
Feb 27 13:18:00 192.168.1.118 system[116]: NTP update successfully, Year:2014,Month:2,Day:27,Hour:13,Min:18,Sec:0
Feb 27 13:18:58 192.168.1.118 system[116]: MemTotal: 28416 kB
Feb 27 13:19:00 192.168.1.118 system[116]: MemFree: 10088 kB
Feb 27 13:21:04 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 20
Feb 27 13:21:04 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 13:21:04 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 30
Feb 27 13:21:04 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 13:21:04 192.168.1.118 sprvoip: cmd 2
Feb 27 13:21:04 192.168.1.118 sprvoip: Seq Num 106
Feb 27 13:21:04 192.168.1.118 sprvoip: cmd - 2, response 2
Feb 27 13:21:04 192.168.1.118 sprvoip: cmd 10, EP 2, Node ID 0
Feb 27 13:21:04 192.168.1.118 sprvoip: cmd - 10, response 10
Feb 27 13:21:04 192.168.1.118 sprvoip: cmd 14, NodeId 0
Feb 27 13:21:04 192.168.1.118 sprvoip: cmd - 14, response 18
Feb 27 13:21:06 192.168.1.118 sprvoip: cmd 16, NodeId 2
Feb 27 13:21:06 192.168.1.118 sprvoip: cmd - 16, response 20
Feb 27 13:21:06 192.168.1.118 sprvoip: cmd 14, NodeId 0
Feb 27 13:21:06 192.168.1.118 sprvoip: cmd - 14, response 18
Feb 27 13:21:06 192.168.1.118 sprvoip: cmd 12, NodeId 0
Feb 27 13:21:06 192.168.1.118 sprvoip: cmd - 12, response 14
Feb 27 13:24:02 192.168.1.118 system[116]: MemTotal: 28416 kB
Feb 27 13:24:03 192.168.1.118 system[116]: MemFree: 10092 kB
Feb 27 13:26:02 192.168.1.118 syslog-ng[345]: STATS: dropped 0
Feb 27 13:27:01 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 20
Feb 27 13:27:01 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 13:27:01 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 30
Feb 27 13:27:01 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 13:27:01 192.168.1.118 sprvoip: cmd 2
Feb 27 13:27:01 192.168.1.118 sprvoip: Seq Num 114
Feb 27 13:27:01 192.168.1.118 sprvoip: cmd - 2, response 2
Feb 27 13:27:01 192.168.1.118 sprvoip: cmd 10, EP 2, Node ID 0
Feb 27 13:27:01 192.168.1.118 sprvoip: cmd - 10, response 10
Feb 27 13:27:01 192.168.1.118 sprvoip: cmd 14, NodeId 0
Feb 27 13:27:01 192.168.1.118 sprvoip: cmd - 14, response 18
Feb 27 13:27:04 192.168.1.118 sprvoip: cmd 16, NodeId 2
Feb 27 13:27:04 192.168.1.118 sprvoip: cmd - 16, response 20
Feb 27 13:27:04 192.168.1.118 sprvoip: cmd 14, NodeId 0
Feb 27 13:27:04 192.168.1.118 sprvoip: cmd - 14, response 18
Feb 27 13:27:04 192.168.1.118 sprvoip: cmd 12, NodeId 0
Feb 27 13:27:04 192.168.1.118 sprvoip: cmd - 12, response 14
Feb 27 13:29:06 192.168.1.118 system[116]: MemTotal: 28416 kB
Feb 27 13:29:08 192.168.1.118 system[116]: MemFree: 9984 kB
Feb 27 13:29:10 192.168.1.118 msgswitchd[219]:   MSGSWD RTCP Reqt len 12 Data 2,4223424,1080793664,211
Feb 27 13:30:01 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 22, ParameterValue 1
Feb 27 13:30:01 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 13:30:01 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 60
Feb 27 13:30:01 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 13:30:01 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 70
Feb 27 13:30:01 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 13:30:01 192.168.1.118 sprvoip: cmd 5, EP 1, ParameterType 22, ParameterValue 1
Feb 27 13:30:01 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 13:30:01 192.168.1.118 sprvoip: cmd 5, EP 1, ParameterType 27, ParameterValue 60
Feb 27 13:30:01 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 13:30:01 192.168.1.118 sprvoip: cmd 5, EP 1, ParameterType 26, ParameterValue 70
Feb 27 13:30:01 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 13:30:06 192.168.1.118 msgswitchd[219]:   MSGSWD RTCP Reqt len 12 Data 2,4223424,1080793664,211
Feb 27 13:30:13 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 20
Feb 27 13:30:13 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 13:30:13 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 30
Feb 27 13:30:13 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 13:30:13 192.168.1.118 sprvoip: cmd 2
Feb 27 13:30:13 192.168.1.118 sprvoip: Seq Num 128
Feb 27 13:30:13 192.168.1.118 sprvoip: cmd - 2, response 2
Feb 27 13:30:13 192.168.1.118 sprvoip: cmd 10, EP 2, Node ID 0
Feb 27 13:30:13 192.168.1.118 sprvoip: cmd - 10, response 10
Feb 27 13:30:13 192.168.1.118 sprvoip: cmd 14, NodeId 0
Feb 27 13:30:13 192.168.1.118 sprvoip: cmd - 14, response 18
Feb 27 13:30:16 192.168.1.118 sprvoip: cmd 16, NodeId 2
Feb 27 13:30:16 192.168.1.118 sprvoip: cmd - 16, response 20
Feb 27 13:30:16 192.168.1.118 sprvoip: cmd 14, NodeId 0
Feb 27 13:30:16 192.168.1.118 sprvoip: cmd - 14, response 18
Feb 27 13:30:16 192.168.1.118 sprvoip: cmd 12, NodeId 0
Feb 27 13:30:16 192.168.1.118 sprvoip: cmd - 12, response 14
Feb 27 13:34:14 192.168.1.118 system[116]: MemTotal: 28416 kB
Feb 27 13:34:15 192.168.1.118 system[116]: MemFree: 9972 kB
Feb 27 13:36:03 192.168.1.118 syslog-ng[345]: STATS: dropped 0
Feb 27 13:38:08 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 20
Feb 27 13:38:08 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 13:38:08 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 30
Feb 27 13:38:08 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 13:38:09 192.168.1.118 sprvoip: cmd 2
Feb 27 13:38:09 192.168.1.118 sprvoip: Seq Num 136
Feb 27 13:38:09 192.168.1.118 sprvoip: cmd - 2, response 2
Feb 27 13:38:09 192.168.1.118 sprvoip: cmd 10, EP 2, Node ID 0
Feb 27 13:38:09 192.168.1.118 sprvoip: cmd - 10, response 10
Feb 27 13:38:09 192.168.1.118 sprvoip: cmd 14, NodeId 0
Feb 27 13:38:09 192.168.1.118 sprvoip: cmd - 14, response 18
Feb 27 13:38:11 192.168.1.118 sprvoip: cmd 16, NodeId 2
Feb 27 13:38:11 192.168.1.118 sprvoip: cmd - 16, response 20
Feb 27 13:38:11 192.168.1.118 sprvoip: cmd 14, NodeId 0
Feb 27 13:38:11 192.168.1.118 sprvoip: cmd - 14, response 18
Feb 27 13:38:11 192.168.1.118 sprvoip: cmd 12, NodeId 0
Feb 27 13:38:11 192.168.1.118 sprvoip: cmd - 12, response 14
Feb 27 13:39:19 192.168.1.118 system[116]: MemTotal: 28416 kB
Feb 27 13:39:20 192.168.1.118 system[116]: MemFree: 10000 kB
Feb 27 13:44:24 192.168.1.118 system[116]: MemTotal: 28416 kB
Feb 27 13:44:25 192.168.1.118 system[116]: MemFree: 10000 kB
Feb 27 13:46:03 192.168.1.118 syslog-ng[345]: STATS: dropped 0
Feb 27 13:49:28 192.168.1.118 system[116]: MemTotal: 28416 kB
Feb 27 13:49:30 192.168.1.118 system[116]: MemFree: 10000 kB
Feb 27 13:54:33 192.168.1.118 system[116]: MemTotal: 28416 kB
Feb 27 13:54:34 192.168.1.118 system[116]: MemFree: 10000 kB
Feb 27 13:56:03 192.168.1.118 syslog-ng[345]: STATS: dropped 0
Feb 27 13:57:45 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 20
Feb 27 13:57:45 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 13:57:45 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 30
Feb 27 13:57:45 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 13:57:45 192.168.1.118 sprvoip: cmd 2
Feb 27 13:57:45 192.168.1.118 sprvoip: Seq Num 144
Feb 27 13:57:45 192.168.1.118 sprvoip: cmd - 2, response 2
Feb 27 13:57:45 192.168.1.118 sprvoip: cmd 10, EP 2, Node ID 0
Feb 27 13:57:45 192.168.1.118 sprvoip: cmd - 10, response 10
Feb 27 13:57:45 192.168.1.118 sprvoip: cmd 14, NodeId 0
Feb 27 13:57:45 192.168.1.118 sprvoip: cmd - 14, response 18
Feb 27 13:57:47 192.168.1.118 sprvoip: cmd 16, NodeId 2
Feb 27 13:57:47 192.168.1.118 sprvoip: cmd - 16, response 20
Feb 27 13:57:47 192.168.1.118 sprvoip: cmd 14, NodeId 0
Feb 27 13:57:47 192.168.1.118 sprvoip: cmd - 14, response 18
Feb 27 13:57:47 192.168.1.118 sprvoip: cmd 12, NodeId 0
Feb 27 13:57:47 192.168.1.118 sprvoip: cmd - 12, response 14
Feb 27 13:59:06 192.168.1.118 msgswitchd[219]:   MSGSWD RTCP Reqt len 12 Data 2,4223424,1080793664,211
Feb 27 13:59:38 192.168.1.118 system[116]: MemTotal: 28416 kB
Feb 27 13:59:39 192.168.1.118 system[116]: MemFree: 9776 kB
Feb 27 14:03:54 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 22, ParameterValue 1
Feb 27 14:03:54 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 14:03:54 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 60
Feb 27 14:03:54 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 14:03:54 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 70
Feb 27 14:03:54 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 14:03:54 192.168.1.118 sprvoip: cmd 5, EP 1, ParameterType 22, ParameterValue 1
Feb 27 14:03:54 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 14:03:54 192.168.1.118 sprvoip: cmd 5, EP 1, ParameterType 27, ParameterValue 60
Feb 27 14:03:54 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 14:03:54 192.168.1.118 sprvoip: cmd 5, EP 1, ParameterType 26, ParameterValue 70
Feb 27 14:03:54 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 14:03:58 192.168.1.118 msgswitchd[219]:   MSGSWD RTCP Reqt len 12 Data 2,4223424,1080793664,211
Feb 27 14:04:02 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 20
Feb 27 14:04:02 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 14:04:02 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 30
Feb 27 14:04:02 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 14:04:02 192.168.1.118 sprvoip: cmd 2
Feb 27 14:04:02 192.168.1.118 sprvoip: Seq Num 158
Feb 27 14:04:02 192.168.1.118 sprvoip: cmd - 2, response 2
Feb 27 14:04:02 192.168.1.118 sprvoip: cmd 10, EP 2, Node ID 0
Feb 27 14:04:02 192.168.1.118 sprvoip: cmd - 10, response 10
Feb 27 14:04:02 192.168.1.118 sprvoip: cmd 14, NodeId 0
Feb 27 14:04:02 192.168.1.118 sprvoip: cmd - 14, response 18
Feb 27 14:04:04 192.168.1.118 sprvoip: cmd 16, NodeId 2
Feb 27 14:04:04 192.168.1.118 sprvoip: cmd - 16, response 20
Feb 27 14:04:04 192.168.1.118 sprvoip: cmd 14, NodeId 0
Feb 27 14:04:04 192.168.1.118 sprvoip: cmd - 14, response 18
Feb 27 14:04:04 192.168.1.118 sprvoip: cmd 12, NodeId 0
Feb 27 14:04:04 192.168.1.118 sprvoip: cmd - 12, response 14
Feb 27 14:04:04 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 20
Feb 27 14:04:04 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 14:04:04 192.168.1.118 sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 30
Feb 27 14:04:04 192.168.1.118 sprvoip: cmd - 5, response 8
Feb 27 14:04:04 192.168.1.118 sprvoip: cmd 2
Feb 27 14:04:04 192.168.1.118 sprvoip: Seq Num 166
Feb 27 14:04:04 192.168.1.118 sprvoip: cmd - 2, response 2
Feb 27 14:04:04 192.168.1.118 sprvoip: cmd 10, EP 2, Node ID 0
Feb 27 14:04:04 192.168.1.118 sprvoip: cmd - 10, response 10
Feb 27 14:04:04 192.168.1.118 sprvoip: cmd 14, NodeId 0
Feb 27 14:04:04 192.168.1.118 sprvoip: cmd - 14, response 18
Feb 27 14:04:08 192.168.1.118 sprvoip: cmd 16, NodeId 2
Feb 27 14:04:08 192.168.1.118 sprvoip: cmd - 16, response 20
Feb 27 14:04:08 192.168.1.118 sprvoip: cmd 14, NodeId 0
Feb 27 14:04:08 192.168.1.118 sprvoip: cmd - 14, response 18
Feb 27 14:04:08 192.168.1.118 sprvoip: cmd 12, NodeId 0
Feb 27 14:04:08 192.168.1.118 sprvoip: cmd - 12, response 14
Feb 27 14:04:42 192.168.1.118 system[116]: MemTotal: 28416 kB
Feb 27 14:04:44 192.168.1.118 system[116]: MemFree: 9776 kB

Dan Lukes · ‎02-27-2014

This is older log that the one you attached in previous post. And, again, it's only log from device's boot. You either:

didn't turned on all the syslog&debug messages
didn't catched all messages sent by device to external syslogd server
no call has arrived from switch to your device

Unfortunatelly, external observer can't decide more. If you are pretty sure you have syslog&debug turned on and you are catching all those messages, then you should verify that call IS arriving from switch to device (e.g. catch the SIP dialog between SIP switch and device)

Just for the completeness, I attached a very short part of debug&syslog messages related to incomming call. Note the exact format depends of syslogd server used, so you may not receive exactly the same messages, but the text part of message is independent from syslogd server.

23:29:54.218898 local3.debug CC_eventProc(), event: CC_EV_SIG_CALL_ARRIVED(0x31), lid: 0, par: 0, par2: 0x407b8900     
23:29:54.219408 local3.debug AUD_ccEventProc: event 49 vid 0 par 0x0 par2 0x407b8900     
23:29:54.219903 local3.debug CC_lineBusy()     
23:29:54.220522 local3.debug getCodecList line 0x22aae8 call 0x22aaec clRemote: 0x407b8990 bInbound 1     
23:29:54.220917 local3.debug pconly: 128     
23:29:54.221359 local3.debug ====== Remote Codec num 2 ======     
23:29:54.221741 local3.debug 8
23:29:54.222109 local3.debug 136
23:29:54.222600 local3.debug =================================     
23:29:54.223177 local3.debug ====== Local codec num 1 ======     
23:29:54.223602 local3.debug 8
23:29:54.223992 local3.debug ================================     
23:29:54.224476 local3.debug [AUD]Get UCH node for AUD_LINE 0 0.     
23:29:54.230492 local3.debug uchAllocateNode(), Node 0 allocated ret=0     
23:29:54.231071 local3.debug [AUD]UCH node 0 allocated to AUD_LINE 0.     
23:29:54.231646 local3.debug uchConnectEpToNode(), connecting EP FXS 1 to node 0

dgrozdanovski · ‎03-06-2014

Today found on Acanac forum, that issues like this could be caused by "do not disturb" feature. However, I never enabled it. Logs never show anything for incoming calls, and caller hears busy signal immediately.

Outcoing calls are visible in the logs. Software phone(x-lite) works fine. Restoring backup fixes issue for a few hours,

Dial tone attached.

Dan Lukes · ‎03-07-2014

Well, catch the SIP dialog between phone and switch. It will reveal if the incomming call is delivered to phone by switch as well as phone's response to it.

Installing and Using Wireshark for Capturing Network Traffic