issues with SPA112 and answering machine

[khavusr]

Recently installed a SPA112 unit which so far works fine and without any bigger issues but have a few minor issues to solve. Among other I can't get the anwering machine to record incoming messages; when there is an incomming call which the answering machine picks up the call the caller gets busy line; meaning that the caller is not able to hear the outgoing message nor able to record?

To be mentioned that I before this was using a Thomson 78x vDSL modem which offered two pots which the same equitment that I'm using was connected to and which also the answering machine worked fine with. So nothng has changed with the setup expect that the SPA112 replaced the Thomson dsl modem when it comes to handle the voip part.

One of the suggestion that I've seen is to change the 'Reorder Delay' to 15 which so far hasn't made any difference.Also, the ring waveform is set to Sinusoid and the default voltage value.

Open for suggestion to point me in the correct direction what to look for in the config for the SPA112.

[Dan Lukes · Accepted solution]

Text format in UCS-16 encoding and time with no seconds can be ignored. But messages are truncated at the first ',' and rest is missing. Second file is the SQLite database ..

You are testing my ability do identify and process obscured data, isn't it ?

Well, I decided to extract the lines from SQLite database as TXT form is incomplete. I know no format if Tm column, fortunately, we need no absolute time and I wish I guessed correct relative time in seconds.

So result (comments embedded):

Incomming call:

002.13  >>> CC_eventProc(), event: CC_EV_SIG_CALL_ARRIVED(0x31), lid: 0, par: 0, par2: 0x40956900
002.16  >>> NEW_CALL_STATE(), call 0: old state = CC_CST_IDLE, new state CC_CST_RINGING
002.16  ::: [0]CID:CID_initGen() >>> offhook 0 delay 1200 phone abcdefg786 name 46bcdefg786
002.23  ::: CID:OnHookTx PolRev

Caller ID transmission:

002.33  >>> uchSendDTMF(), sending DTMF 12 to line 0
002.33  ::: [0]CID Start DTMF/FSK, CID_ST_ACTIVE
002.48  >>> uchSendDTMF(), sending DTMF a to line 0
002.64  >>> uchSendDTMF(), sending DTMF b to line 0
002.80  >>> uchSendDTMF(), sending DTMF c to line 0
002.96  >>> uchSendDTMF(), sending DTMF d to line 0
003.13  >>> uchSendDTMF(), sending DTMF e to line 0
003.29  >>> uchSendDTMF(), sending DTMF f to line 0
003.45  >>> uchSendDTMF(), sending DTMF g to line 0
003.61  >>> uchSendDTMF(), sending DTMF 7 to line 0
003.77  >>> uchSendDTMF(), sending DTMF 8 to line 0
003.93  >>> uchSendDTMF(), sending DTMF 6 to line 0
004.08  >>> uchSendDTMF(), sending DTMF 14 to line 0
004.25  ::: [0]CID CID:DONE

Six rings:

004.52  ::: CID:Ring Now
004.54  >>> SLIC_startRing state 0 ts 0x1aa4ccon 1000 off 5000 len 60000
004.54  >>> [0]Ring cad event 0 pol 0
009.33  >>> [0]Ring cad event 0 pol 0
014.12  >>> [0]Ring cad event 0 pol 0
018.92  >>> [0]Ring cad event 0 pol 0
023.73  >>> [0]Ring cad event 0 pol 0
028.52  >>> [0]Ring cad event 0 pol 0

Off hook:

029.50  >>> [0]Off Hook
029.51  >>> NEW_CALL_STATE(), call 0: old state = CC_CST_RINGING, new state CC_CST_ANSWERING

Call fully connected:

029.57  >>> NEW_CALL_STATE(), call 0: old state = CC_CST_ANSWERING, new state CC_CST_CONNECTED

Disconnected from remote side:

039.62  >>> SIP_sessDlgEventProc: event: 45(SIP_EV_DLG_BYED), ucState: 3
039.62  >>> NEW_CALL_STATE(), call 0: old state = CC_CST_CONNECTED, new state CC_CST_INVALID

CPC sent to called device:

047.64  >>> CPC SLIC_SET_OPEN_STATE on line 0
048.05  >>> CPC go to CC_CST_IDLE line 0
048.05  >>> NEW_CALL_STATE(), call 0: old state = CC_CST_INVALID, new state CC_CST_IDLE

Called device still off hook, assuming new (outgoing) call:

048.07  >>> cepIdleProc(lid=0, call=0x17a974, event=9(CC_EV_USR_SEIZURE), par=0, par2=(nil))
048.07  >>> NEW_CALL_STATE(), call 0: old state = CC_CST_IDLE, new state CC_CST_DIALING   

Called device on-hook, call cleanup:
048.72  >>> [0]On Hook
048.73  >>> NEW_CALL_STATE(), call 0: old state = CC_CST_DIALING, new state CC_CST_IDLE

Device off hook, outgoing call starts, collecting dialed digits:

060.05  >>> [0]Off Hook
060.06  >>> cepIdleProc(lid=0, call=0x17a974, event=9(CC_EV_USR_SEIZURE), par=0, par2=(nil))
060.07  >>> NEW_CALL_STATE(), call 0: old state = CC_CST_IDLE, new state CC_CST_DIALING
065.20  >>> SIP_sessDlgEventProc: event: 41(SIP_EV_DLG_TERM), ucState: 4

Device on hook again, no digit has been received in this round:

066.01  >>> [0]On Hook
066.01  >>> NEW_CALL_STATE(), call 0: old state = CC_CST_DIALING, new state CC_CST_IDLE

Device off hook, outgoing call starts, collecting dialed digits:

079.17  >>> [0]Off Hook
079.19  >>> NEW_CALL_STATE(), call 0: old state = CC_CST_IDLE, new state CC_CST_DIALING
081.68  >>> line:0 DTMFON event received digit a
081.81  >>> line:0 DTMFON event received digit b
081.94  >>> line:0 DTMFON event received digit c
082.07  >>> line:0 DTMFON event received digit d
082.20  >>> line:0 DTMFON event received digit e
082.36  >>> line:0 DTMFON event received digit f
082.49  >>> line:0 DTMFON event received digit g
082.62  >>> line:0 DTMFON event received digit 7
082.76  >>> line:0 DTMFON event received digit 8
082.89  >>> line:0 DTMFON event received digit 6
090.96  >>> cepDialingProc(), event = 33(CC_EV_TMR_DIALPLAN)

Digits are collected (dialing commited by dial plan timeout):

090.96  >>> NEW_CALL_STATE(), call 0: old state = CC_CST_DIALING, new state CC_CST_CALLING
090.97  ::: Calling:abcdefg786@bahnhof-lda.soho1.voip.bahnhof.net:0, rc=0
091.47  >>> NEW_CALL_STATE(), call 0: old state = CC_CST_CALLING, new state CC_CST_PROCEEDING

REGISTER procedure has been fired and completed during the call setup:

097.66  >>> [0]RegOK. NextReg in 296 (1)

Call fully connected:

099.05  >>> NEW_CALL_STATE(), call 0: old state = CC_CST_PROCEEDING, new state CC_CST_CONNECTED

Disconnected from remote side:

103.75  >>> SIP_sessDlgEventProc: event: 45(SIP_EV_DLG_BYED), ucState: 3
103.76  >>> NEW_CALL_STATE(), call 0: old state = CC_CST_CONNECTED, new state CC_CST_INVALID

CPC sent to calling device:

103.76  >>> CPC statr timer CC_EV_TMR_INVALID
111.76  >>> CPC SLIC_SET_OPEN_STATE on line 0
112.19  >>> CPC go to CC_CST_IDLE line 0
112.19  >>> NEW_CALL_STATE(), call 0: old state = CC_CST_INVALID, new state CC_CST_IDLE

Device still off hook, assuming new (outgoing) call:

112.22  >>> NEW_CALL_STATE(), call 0: old state = CC_CST_IDLE, new state CC_CST_DIALING
Hook flash event occurred. Call 0 (collecting digits) cancelled. New call (1)
created, collecting digits:

112.37  >>> [0]Hook Flash
112.37  >>> CC_eventProc(), event: CC_EV_USR_HOOKFLASH(0x3), lid: 0, par: 0, par2: (nil)
112.37  >>> NEW_CALL_STATE(), call 0: old state = CC_CST_DIALING, new state CC_CST_IDLE
112.43  >>> NEW_CALL_STATE(), call 1: old state = CC_CST_IDLE, new state CC_CST_DIALING

No digit dialed, dialing timeout fired:

136.34  >>> NEW_CALL_STATE(), call 1: old state = CC_CST_DIALING, new state CC_CST_INVALID

Line is still of hook at the end of log.

Well. So we have commented log. Now - whats your question ?

Note that CPC Signal (Calling Party Control Signal) is a momentary drop in voltage (0 volts DC) on the line for a period of time. It's the way how the "server" side of analog line (SPA112 here) inform calling device (your machine here) that call has been disconnected by called side. Also, Cisco is using CPC to signal remote disconnection even it the case of incoming calls despite CPC has not been intended for such call direction.

Not every phone can recognize CPC signal, especially when called. SPA112 needs to be configured according capabilities of particular phone.

[khavusr]

Hi Dan,

thanks for the log decoding and for baring with me regarding the syslog issues; seems that the 3 different software packages I've tested for Windows have some ups and downs.

For the specific question; what I was looking for is whether there are some major issues that you could see that needs to be tweaked. Is my assumption correct that incoming SIP traffic works as it should? You confirmed that the outgoing from the SPA112 worked and that no SIP traffic came through due to most likely to the fw and nat issues.

So based on the log; would it be considered that the SIP flows as it should basedon what you can identify or do you still see the issue with missing incoming SIP traffic?

[Dan Lukes]

I see no signs of major issue in the log.

Note that you didn't captured (or disclosed) the SIP packets, so it's hard to decide if there's something wrong with it. The log is indirect source of such kind of information. But if you has been successful making both incoming and outgoing calls (including bidirectional audio) there should not be major issue.

Well, there is minor issue related to answering machine hangup procedure which seems not to be so fast but I assume it will not cause noticeable issues to you.

[khavusr]

It's odd that the syslog didn't capture the SIP packages; don't know why and as I did enable the syslog with debuging level 3. Either it's the SPA112 who doesn't include them in the syslog or it's something else. Happy to continue on this track to figure out why it's not working; but based on input from you.

But, as said, it seems that everything is working now as it should with incoming and outgoing calls. The anwering machine is picking-up the calls as it should and I'm also able to control the answering machine from remote using dtmf codes.

To summarize the issue identified here, as you pointed out seems to be the missing of incoming SIP traffic flow based on fw/nat rules. This was a correct observation from your side. Bahnhof is using SIP proxy which has at least 6 different IP's in a cluster. So what I've done for the SIP traffic is that I've created an address list with the currently, so far, 6 know IP's behind the proxy which is used for the NAT rule itself. What I'll do is also monitor incoming traffic from the network segment used by the proxy to see if there are additional IP's showing up to be added to the address lists.

Also, from Bahnhof perspective their not familar with this issues due to the fact that they 1) don't give you support on your own equipment and 2) for the voip customers who's using Bahnhof own ATA's it's placed the infront of the fw.

And finally; thanks for being patient and for rapid responses; highly appreciated.

[Dan Lukes]

For the purpose of analysis various network issues the network administrator needs to be able to catch packets on the wire anyway. So it can catch SIP packets directly. It's rather overkill to sent a packet twice - as a SIP packet and once more, embedded in syslog message. It may overload phone, network infrastructure or syslog server as well.

thanks for being patient and for rapid responses; highly appreciated.

Glad to hear it helped. You should use rating ("stars") to appreciate helpful responses. Rated thread become more helpful for other users, so the time spent to analysis will not have one-time effect only. Note I'm not pushing you to give five start to all responses around. Just give feedback according your feeling.

[khavusr]

Five star it is! While on the topic when it comes to configure the SPA112; but are you aware if there are any recommendation on how to confugre the SPA112 based on region and what parameters which are wiorth looking into. While I usually live by the motto of not touching or changing something that works... In this particular case I would like to tweak for the best possible audio as possible and only thing that I've noticed is that I have a hearble white noise in the background and sometimes a slight echo of my own voice. Specifics for this would be of interest.

[khavusr]

Syslog update; additional data and among other I now have the dropped calls from voice messaging service which tries to read out the previous text messages from mobile phone.
 

Update: Removing log file.