Topic: Greetings

[Graham]

When trying to record a greeting using *60* the recording is in slow motion, but when playing back a previous greeting with  *61* it’s fine.

[Graham]

Correction this also affects calls

[SARK devs]

Are you running under VM?

[Graham]

Nope not VM, it was working fine

I've started using a new phone Pirelli DP-L10

[Graham]

Looked at this a bit more and it now seems the outbound sound works fine until I try and record a greeting then all calls after that the outbound sound slowed down.

[SARK devs]

What release do you have?

[Graham]

sail-2.2.1-708

[SARK devs]

I can't recreate this Graham.  Works perfectly on our reference rig.  I'm not even sure where to go with it because this stuff is all raw asterisk.  Perhaps if you could relate what changed before the the problem emerged and also run a verbose console log of the recording process with agi debug turned on.  Maybe we'll be able to see some unexpected state change within asterisk.  Also, do you get the same results using a different phone? 

Best

S

[Graham]

Only seems to do it with DP-L10, X-Lite seems fine.

I’ve tried a few things and this is what I ended up with.

1)   Received an incoming call, outbound sound was fine.
2)   Made call to *60* and recorded a greeting, playback was slowed down.
3)   Received an incoming call, outbound sound was slowed down same as with greeting.
4)   Turned DP-L10 off and on and everything works fine until you try and recorded a greeting.

When I say recorded a greeting it also does it when you dial another extn from the DP-L10 and leave a voicemail.

Below is the debug output, the first one is of me calling to create a greeting and the second one is showing the inbound call after making a call to create a greeting.

Greeting

server-1*CLI> agi debug
AGI Debugging Enabled
    -- Executing [*60*3003@internal:1] BackGround("SIP/5001-09375438", "silence/1") in new stack
    -- <SIP/5001-09375438> Playing 'silence/1' (language 'en')
    -- Executing [*60*3003@internal:2] AGI("SIP/5001-09375438", "selintra|*60*3003") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/selintra
AGI Tx >> agi_request: selintra
AGI Tx >> agi_channel: SIP/5001-09375438
AGI Tx >> agi_language: en
AGI Tx >> agi_type: SIP
AGI Tx >> agi_uniqueid: 1232222591.16
AGI Tx >> agi_callerid: 5001
AGI Tx >> agi_calleridname: Wireless
AGI Tx >> agi_callingpres: 0
AGI Tx >> agi_callingani2: 0
AGI Tx >> agi_callington: 0
AGI Tx >> agi_callingtns: 0
AGI Tx >> agi_dnid: *60*3003
AGI Tx >> agi_rdnis: unknown
AGI Tx >> agi_context: internal
AGI Tx >> agi_extension: *60*3003
AGI Tx >> agi_priority: 2
AGI Tx >> agi_enhanced: 0.0
AGI Tx >> agi_accountcode:
AGI Tx >>
AGI Rx << GET VARIABLE EXTLEN
AGI Tx >> 200 result=1 ()
AGI Rx << EXEC Authenticate 0306
    -- AGI Script Executing Application: (Authenticate) Options: (0306)
    -- <SIP/5001-09375438> Playing 'agent-pass' (language 'en')
    -- <SIP/5001-09375438> Playing 'auth-thankyou' (language 'en')
AGI Tx >> 200 result=0
AGI Rx << EXEC Playback pm-announcement-number
    -- AGI Script Executing Application: (Playback) Options: (pm-announcement-number)
[Jan 17 20:03:21] WARNING[9247]: file.c:602 ast_openstream_full: File pm-announcement-number does not exist in any format
[Jan 17 20:03:21] WARNING[9247]: file.c:912 ast_streamfile: Unable to open pm-announcement-number (format 0x4 (ulaw)): No such file or directory
[Jan 17 20:03:21] WARNING[9247]: app_playback.c:439 playback_exec: ast_streamfile failed on SIP/5001-09375438 for pm-announcement-number
AGI Tx >> 200 result=0
AGI Rx << EXEC SayDigits 3003
    -- AGI Script Executing Application: (SayDigits) Options: (3003)
    -- <SIP/5001-09375438> Playing 'digits/3' (language 'en')
    -- <SIP/5001-09375438> Playing 'digits/0' (language 'en')
    -- <SIP/5001-09375438> Playing 'digits/0' (language 'en')
    -- <SIP/5001-09375438> Playing 'digits/3' (language 'en')
AGI Tx >> 200 result=0
AGI Rx << EXEC Playback is-now-being-recorded
    -- AGI Script Executing Application: (Playback) Options: (is-now-being-recorded)
[Jan 17 20:03:23] WARNING[9247]: file.c:602 ast_openstream_full: File is-now-being-recorded does not exist in any format
[Jan 17 20:03:23] WARNING[9247]: file.c:912 ast_streamfile: Unable to open is-now-being-recorded (format 0x4 (ulaw)): No such file or directory
[Jan 17 20:03:23] WARNING[9247]: app_playback.c:439 playback_exec: ast_streamfile failed on SIP/5001-09375438 for is-now-being-recorded
AGI Tx >> 200 result=0
AGI Rx << EXEC Playback press-pound-save-changes
    -- AGI Script Executing Application: (Playback) Options: (press-pound-save-changes)
[Jan 17 20:03:23] WARNING[9247]: file.c:602 ast_openstream_full: File press-pound-save-changes does not exist in any format
[Jan 17 20:03:23] WARNING[9247]: file.c:912 ast_streamfile: Unable to open press-pound-save-changes (format 0x4 (ulaw)): No such file or directory
[Jan 17 20:03:23] WARNING[9247]: app_playback.c:439 playback_exec: ast_streamfile failed on SIP/5001-09375438 for press-pound-save-changes
AGI Tx >> 200 result=0
AGI Rx << RECORD FILE usergreetingtemp gsm "#" 30000 BEEP s=10
    -- <SIP/5001-09375438> Playing 'beep' (language 'en')
AGI Tx >> 200 result=35 (dtmf) endpos=220320
AGI Rx << STREAM FILE usergreetingtemp "" 0
    -- Playing 'usergreetingtemp' (escape_digits=) (sample_offset 0)
AGI Tx >> 200 result=0 endpos=220320
AGI Rx << STREAM FILE save-announce-press "123" 0
[Jan 17 20:04:01] WARNING[9247]: file.c:602 ast_openstream_full: File save-announce-press does not exist in any format
AGI Tx >> 200 result=0 endpos=0
AGI Rx << STREAM FILE digits/1 "123" 0
    -- Playing 'digits/1' (escape_digits=123) (sample_offset 0)
AGI Tx >> 200 result=0 endpos=5280
AGI Rx << STREAM FILE to-rerecord-announce "123" 0
[Jan 17 20:04:01] WARNING[9247]: file.c:602 ast_openstream_full: File to-rerecord-announce does not exist in any format
AGI Tx >> 200 result=0 endpos=0
AGI Rx << STREAM FILE digits/2 "123" 0
    -- Playing 'digits/2' (escape_digits=123) (sample_offset 0)
AGI Tx >> 200 result=0 endpos=4800
AGI Rx << STREAM FILE to-cancel-this-msg "123" 0
[Jan 17 20:04:02] WARNING[9247]: file.c:602 ast_openstream_full: File to-cancel-this-msg does not exist in any format
AGI Tx >> 200 result=0 endpos=0
AGI Rx << STREAM FILE press "123" 0
[Jan 17 20:04:02] WARNING[9247]: file.c:602 ast_openstream_full: File press does not exist in any format
AGI Tx >> 200 result=0 endpos=0
AGI Rx << STREAM FILE digits/3 "123" 0
    -- Playing 'digits/3' (escape_digits=123) (sample_offset 0)
AGI Tx >> 200 result=0 endpos=4800
AGI Rx << STREAM FILE silence/5 "123" 0
    -- Playing 'silence/5' (escape_digits=123) (sample_offset 0)
AGI Tx >> 200 result=49 endpos=14080
AGI Rx << EXEC Playback your-msg-has-been-saved
    -- AGI Script Executing Application: (Playback) Options: (your-msg-has-been-saved)
[Jan 17 20:04:04] WARNING[9247]: file.c:602 ast_openstream_full: File your-msg-has-been-saved does not exist in any format
[Jan 17 20:04:04] WARNING[9247]: file.c:912 ast_streamfile: Unable to open your-msg-has-been-saved (format 0x4 (ulaw)): No such file or directory
[Jan 17 20:04:04] WARNING[9247]: app_playback.c:439 playback_exec: ast_streamfile failed on SIP/5001-09375438 for your-msg-has-been-saved
AGI Tx >> 200 result=0
AGI Rx << EXEC Playback goodbye
    -- AGI Script Executing Application: (Playback) Options: (goodbye)
[Jan 17 20:04:04] WARNING[9247]: file.c:602 ast_openstream_full: File goodbye does not exist in any format
[Jan 17 20:04:04] WARNING[9247]: file.c:912 ast_streamfile: Unable to open goodbye (format 0x4 (ulaw)): No such file or directory
[Jan 17 20:04:04] WARNING[9247]: app_playback.c:439 playback_exec: ast_streamfile failed on SIP/5001-09375438 for goodbye
AGI Tx >> 200 result=0
    -- AGI Script selintra completed, returning 0
  == Auto fallthrough, channel 'SIP/5001-09375438' status is 'UNKNOWN'
    -- Executing [h@internal:1] Hangup("SIP/5001-09375438", "") in new stack
  == Spawn extension (internal, h, 1) exited non-zero on 'SIP/5001-09375438'
agi no debug
AGI Debugging Disabled

Incoming Call

server-1*CLI> agi debug
AGI Debugging Enabled
    -- Executing [9883008@mainmenu:1] AGI("SIP/9883008-09375438", "selintra|Inbound|9883008") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/selintra
AGI Tx >> agi_request: selintra
AGI Tx >> agi_channel: SIP/9883008-09375438
AGI Tx >> agi_language: en
AGI Tx >> agi_type: SIP
AGI Tx >> agi_uniqueid: 1232223165.17
AGI Tx >> agi_callerid: xxxxxxxxxxx
AGI Tx >> agi_calleridname: xxxxxxxxxxx
AGI Tx >> agi_callingpres: 0
AGI Tx >> agi_callingani2: 0
AGI Tx >> agi_callington: 0
AGI Tx >> agi_callingtns: 0
AGI Tx >> agi_dnid: 9883008
AGI Tx >> agi_rdnis: unknown
AGI Tx >> agi_context: mainmenu
AGI Tx >> agi_extension: 9883008
AGI Tx >> agi_priority: 1
AGI Tx >> agi_enhanced: 0.0
AGI Tx >> agi_accountcode:
AGI Tx >> LI>
AGI Rx << GET VARIABLE EXTLEN
AGI Tx >> 200 result=1 ()
AGI Rx << GET VARIABLE EXTLEN
AGI Tx >> 200 result=1 ()
AGI Rx << GET VARIABLE RINGDELAY
AGI Tx >> 200 result=1 (0)
AGI Rx << GET VARIABLE FAXDETECT
AGI Tx >> 200 result=1 (2)
AGI Rx << GET VARIABLE CALLRECORD2
AGI Tx >> 200 result=1 (None)
AGI Rx << GET VARIABLE LTERM
AGI Tx >> 200 result=1 (NO)
AGI Rx << SET VARIABLE MOH ""
AGI Tx >> 200 result=1
AGI Rx << SET CALLERID xxxxxxxxxxx
AGI Tx >> 200 result=1
AGI Rx << DATABASE GET "STAT" "OCSTAT"
AGI Tx >> 200 result=0
AGI Rx << SET VARIABLE REMOTENUM "9883008"
AGI Tx >> 200 result=1
AGI Rx << GET VARIABLE MTIME
AGI Tx >> 200 result=1 (ON)
AGI Rx << GET VARIABLE IFTIME(22:00-09:00|*|*|*?CLOSED:OPEN)
AGI Tx >> 200 result=1 (OPEN)
AGI Rx << GET VARIABLE VOICEINSTR
AGI Tx >> 200 result=1 (YES)
AGI Rx << SET VARIABLE OPEN "YES"
AGI Tx >> 200 result=1
AGI Rx << DATABASE GET "STAT" "IVRSTAT"
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE SYSOP
AGI Tx >> 200 result=1 (1001)
AGI Rx << SET PRIORITY 1
AGI Tx >> 200 result=0
AGI Rx << SET EXTENSION 5001
AGI Tx >> 200 result=0
AGI Rx << SET CONTEXT internal
AGI Tx >> 200 result=0
    -- AGI Script selintra completed, returning 0
    -- Executing [5001@internal:1] AGI("SIP/9883008-09375438", "selintra|OutCluster|5001") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/selintra
AGI Tx >> agi_request: selintra
AGI Tx >> agi_channel: SIP/9883008-09375438
AGI Tx >> agi_language: en
AGI Tx >> agi_type: SIP
AGI Tx >> agi_uniqueid: 1232223165.17
AGI Tx >> agi_callerid: xxxxxxxxxxx
AGI Tx >> agi_calleridname: unknown
AGI Tx >> agi_callingpres: 0
AGI Tx >> agi_callingani2: 0
AGI Tx >> agi_callington: 0
AGI Tx >> agi_callingtns: 0
AGI Tx >> agi_dnid: 9883008
AGI Tx >> agi_rdnis: unknown
AGI Tx >> agi_context: internal
AGI Tx >> agi_extension: 5001
AGI Tx >> agi_priority: 1
AGI Tx >> agi_enhanced: 0.0
AGI Tx >> agi_accountcode:
AGI Tx >>
AGI Rx << GET VARIABLE EXTLEN
AGI Tx >> 200 result=1 ()
AGI Rx << SET PRIORITY 1
AGI Tx >> 200 result=0
AGI Rx << SET EXTENSION 5001
AGI Tx >> 200 result=0
AGI Rx << SET CONTEXT default
AGI Tx >> 200 result=0
    -- AGI Script selintra completed, returning 0
    -- Executing [5001@default:1] AGI("SIP/9883008-09375438", "selintra|InCall|") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/selintra
AGI Tx >> agi_request: selintra
AGI Tx >> agi_channel: SIP/9883008-09375438
AGI Tx >> agi_language: en
AGI Tx >> agi_type: SIP
AGI Tx >> agi_uniqueid: 1232223165.17
AGI Tx >> agi_callerid: xxxxxxxxxxx
AGI Tx >> agi_calleridname: unknown
AGI Tx >> agi_callingpres: 0
AGI Tx >> agi_callingani2: 0
AGI Tx >> agi_callington: 0
AGI Tx >> agi_callingtns: 0
AGI Tx >> agi_dnid: 9883008
AGI Tx >> agi_rdnis: unknown
AGI Tx >> agi_context: default
AGI Tx >> agi_extension: 5001
AGI Tx >> agi_priority: 1
AGI Tx >> agi_enhanced: 0.0
AGI Tx >> agi_accountcode:
AGI Tx >>
AGI Rx << GET VARIABLE EXTLEN
AGI Tx >> 200 result=1 ()
AGI Rx << GET VARIABLE EXTLEN
AGI Tx >> 200 result=1 ()
AGI Rx << GET VARIABLE BLINDTRANSFER
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE VOICEINSTR
AGI Tx >> 200 result=1 (YES)
AGI Rx << DATABASE GET "STAT" "OCSTAT"
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE MTIME
AGI Tx >> 200 result=1 (ON)
AGI Rx << DATABASE GET "cfimopen" "5001"
AGI Tx >> 200 result=0
AGI Rx << DATABASE GET "cfim" "5001"
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE EXTLEN
AGI Tx >> 200 result=1 ()
AGI Rx << DATABASE GET "STAT" "OCSTAT"
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE MTIME
AGI Tx >> 200 result=1 (ON)
AGI Rx << GET VARIABLE VOICEINSTR
AGI Tx >> 200 result=1 (YES)
AGI Rx << DATABASE GET "cfimopen" "5001"
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE EXTLEN
AGI Tx >> 200 result=1 ()
AGI Rx << DATABASE GET "STAT" "OCSTAT"
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE MTIME
AGI Tx >> 200 result=1 (ON)
AGI Rx << GET VARIABLE VOICEINSTR
AGI Tx >> 200 result=1 (YES)
AGI Rx << DATABASE GET "cfim" "5001"
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE EXTLEN
AGI Tx >> 200 result=1 ()
AGI Rx << DATABASE GET "ringdelay" "5001"
AGI Tx >> 200 result=0
AGI Rx << GET VARIABLE INTRINGDELAY
AGI Tx >> 200 result=1 (30)
AGI Rx << GET VARIABLE CALLRECORD1
AGI Tx >> 200 result=1 (None)
AGI Rx << GET VARIABLE CALLRECORD2
AGI Tx >> 200 result=1 (None)
AGI Rx << GET VARIABLE MOH
AGI Tx >> 200 result=1 ()
AGI Rx << EXEC Dial SIP/5001|30|t
    -- AGI Script Executing Application: (Dial) Options: (SIP/5001|30|t)
    -- Called 5001
    -- SIP/5001-093a5c10 is ringing
    -- SIP/5001-093a5c10 answered SIP/9883008-09375438
AGI Tx >> 200 result=-1
  == Spawn extension (default, 5001, 1) exited non-zero on 'SIP/9883008-09375438'
    -- Executing [h@default:1] Hangup("SIP/9883008-09375438", "") in new stack
  == Spawn extension (default, h, 1) exited non-zero on 'SIP/9883008-09375438'
agi no debug
AGI Debugging Disabled

[SARK devs]

ok - nothing obvious there.  Usually if a digital recording sounds slow it's caused by having the record sample rate set higher than the play back algorithm is expecting.  Some of the newer phones on the market support HD sound (for example the new SNOMs have it).  I'm wondering if maybe your DP-L10 has such a feature and you are perhaps inadvertently turning it on and off with our feature codes?


S

[Graham]

Is this a phone bug, tried an echo test and it's fine.

This issue only seems to happen when making a recording.

How do you reset asterisk stop start button doesn’t seem to be working.

[SARK devs]

I don't know if it is a phone bug but I'm pretty sure it is a phone issue.  STOP/START won#t always work if you've been using the asterisk console.

To do a clean restart; at the Linux console do...

Code: [Select]

/etc/init.d/sark stop
/etc/init.d/sark start
Best

S

[Graham]

Seems restarting asterisk doesn’t fix the outbound call speed only restarting the phone does.

Also If I leave a voicemail and at the end don’t press # then the next inbound calls outbound sound is fine, but if I do press # at the end of a voicemail then it isn’t

Even more odd if I press # during a call it does a transfer that’s fine, and I abort the transfer but after that the outbound sound is broken, so it’s something to do with pressing #

Also I get this when starting asterisk:

[root@server-1 ~]# /etc/init.d/sark start
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature
FATAL: Module zaptel not found.
Waiting for udev.
Notice: Configuration file is /etc/zaptel.conf
line 0: Unable to open master device '/dev/zap/ctl'

1 error(s) detected

Starting asterisk:                                         [  OK  ]

[SARK devs]

Code: [Select]

[root@server-1 ~]# /etc/init.d/sark start
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature

you can ignore the above messages it has something to do with the way in which ATrpms build their rpms - its annoying but benign.

Code: [Select]

FATAL: Module zaptel not found.
Waiting for udev.
Notice: Configuration file is /etc/zaptel.conf
line 0: Unable to open master device '/dev/zap/ctl'

1 error(s) detected
This is more worrying, you either do not have zaptel installed or you have done a yum update and downloaded a new kernel without handling zaptel-kmdl.

what does 'uname -r' return at the linux console?

what does 'rpm-qa | grep zaptel-kmdl' return?

Neither of these things should mess up playback speed (although they may make it a little choppy), however its a good idea to fix it before you do anything else.

You can turn off hash processing (at least for transfers)in headers->features.conf...  set blindxfer=##

Did you check the phone manual to see what # does (if anything) and whether it supports highdef audio?

Best

S

 

 

[Graham]

All the updates I do are via SME

[root@server-1 ~]# uname -r
2.6.9-78.0.8.EL

[root@server-1 ~]# rpm -qa | grep zaptel-kmdl
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature
warning: only V3 signatures can be verified, skipping V4 signature