Vgetty script problems

Moe Pitman (mpitman@uni-market.com)
Thu, 12 Aug 1999 01:50:38 -0500
Messages sorted by:[ date ][ thread ][ subject ][ author ]
Marc SCHAEFER wrote:

> Moe Pitman <mpitman@uni-market.com> wrote:
> > It works flawlessly using the default behavior with no script.
>
> Which is I suppose the log you sent.

Sigh.  Yes.  I hope the one included below is more informative (log level 6)

>
>
> > Using the supplied demo.sh script (or any other), it will answer, play
> > the greeting, and record, but it won't terminate the recording.  I have
>
> Bizarre, to the least. It does not even stop after rec_max_len ?
> (see voice.conf) or after a hangup ?
> Does the RMD file really grow during that period ?

I have rec_max_len set rather high (15 min ) because some of the anticipated
messages might be that long.  But a hangup does not terminate the message,
and the RMD file continues to grow, recording the "If you'd like to make a
call..." message and the annoying off-hook tones that follow.  Killing
vgetty is the only way I've been able to terminate it.

After messing around with the scripts, though, I can't repeat that
behavior...

The following log was recorded during the _other_ problem I've been having
since I wrote the first message, that is having the script hang up
immediately and record nothing.  This is with the (almost) stock demo.pl
script -- I changed the playback file to /var/spool/voice/messages/welcome,
since I already had that file in place.

The suspicious entries (to me) seem to start with "start_play_command
failed".  I don't know why it fails.

Here is the section of the log file immediately following the conf & key
sections, up to releasing the lock file at the end of the call:

----------------------------------------------------------------------
08/12 01:36:52 yS0    vgetty: answer mode was set directly
08/12 01:36:52 yS0    vgetty: answer mode is [data|fax|voice]
08/12 01:36:52 yS0    vgetty: opening list file
/var/spool/voice/messages/Index
08/12 01:36:52 yS0    vgetty: found 1 messages, picked message number 1
08/12 01:36:52 yS0    vgetty: message name is
/var/spool/voice/messages/welcome
08/12 01:36:52 yS0   vgetty: entering voice mode
08/12 01:36:52 yS0   vgetty: Installing signal handlers
08/12 01:36:52 yS0   voice command: 'AT#CLS?' -> ''
08/12 01:36:53 yS0    vgetty: AT#CLS?
08/12 01:36:53 yS0    US Robotics: AT#CLS?
08/12 01:36:53 yS0    US Robotics: 2.0
08/12 01:36:53 yS0   voice command: '' -> 'OK'
08/12 01:36:53 yS0    US Robotics: OK
08/12 01:36:53 yS0   voice command: 'AT#CLS=8' -> 'OK'
08/12 01:36:53 yS0    vgetty: AT#CLS=8
08/12 01:36:53 yS0    US Robotics: AT#CLS=8
08/12 01:36:53 yS0    US Robotics: OK
08/12 01:36:53 yS0   voice command: 'AT' -> 'OK'
08/12 01:36:53 yS0    vgetty: AT
08/12 01:36:53 yS0    US Robotics: AT
08/12 01:36:53 yS0    US Robotics: OK
08/12 01:36:53 yS0   voice command:
'AT#VTD=3F,3F,3F#VSD=1#VSS=1#VSP=70#VRA=70#VRN=100' -> 'OK'
08/12 01:36:53 yS0    vgetty:
AT#VTD=3F,3F,3F#VSD=1#VSS=1#VSP=70#VRA=70#VRN=100
08/12 01:36:53 yS0    US Robotics:
AT#VTD=3F,3F,3F#VSD=1#VSS=1#VSP=70#VRA=70#VRN=100
08/12 01:36:53 yS0    US Robotics: OK
08/12 01:36:53 yS0   voice command: 'AT#VLS=0A' -> 'VCON'
08/12 01:36:54 yS0    vgetty: AT#VLS=0A
08/12 01:36:54 yS0    US Robotics: AT#VLS=0A
08/12 01:36:54 yS0    US Robotics: VCON
08/12 01:36:54 yS0    vgetty: queued event RESET_WATCHDOG at position 0001
08/12 01:36:54 yS0   voice command: 'AT#VLS=0' -> 'OK|VCON'
08/12 01:36:54 yS0    vgetty: AT#VLS=0
08/12 01:36:54 yS0    vgetty: unqueued event RESET_WATCHDOG at position 0001

08/12 01:36:54 yS0    vgetty: voice_handle_event got event RESET_WATCHDOG
with data <_>
08/12 01:36:54 yS0    US Robotics: AT#VLS=0
08/12 01:36:54 yS0    US Robotics: OK
08/12 01:36:54 yS0  vgetty: Executing shell script /usr/local/bin/demo.pl
with shell /bin/bash
08/12 01:36:54 yS0    vgetty: opening pipes
08/12 01:36:54 yS0    vgetty: forking shell
08/12 01:36:54 yS0   vgetty(0): HELLO SHELL
08/12 01:36:54 yS0    vgetty: Got pipe signal
08/12 01:36:54 yS0    vgetty: queued event SIGNAL_SIGPIPE at position 0002
08/12 01:36:54 yS0    vgetty: unqueued event SIGNAL_SIGPIPE at position 0002

08/12 01:36:54 yS0    vgetty: voice_handle_event got event SIGNAL_SIGPIPE
with data <_>
08/12 01:36:54 yS0   shell(1): HELLO VOICE PROGRAM
08/12 01:36:54 yS0   vgetty(1): READY
08/12 01:36:54 yS0   vgetty: initialized communication
08/12 01:36:54 yS0    vgetty: Got pipe signal
08/12 01:36:54 yS0    vgetty: queued event SIGNAL_SIGPIPE at position 0003
08/12 01:36:54 yS0    vgetty: unqueued event SIGNAL_SIGPIPE at position 0003

08/12 01:36:54 yS0    vgetty: voice_handle_event got event SIGNAL_SIGPIPE
with data <_>
08/12 01:36:54 yS0   shell(1): DEVICE DIALUP_LINE
08/12 01:36:54 yS0    vgetty: queued event RESET_WATCHDOG at position 0004
08/12 01:36:54 yS0   voice command: 'AT#VLS=0' -> 'OK|VCON'
08/12 01:36:54 yS0    vgetty: AT#VLS=0
08/12 01:36:54 yS0    vgetty: unqueued event RESET_WATCHDOG at position 0004

08/12 01:36:54 yS0    vgetty: voice_handle_event got event RESET_WATCHDOG
with data <_>
08/12 01:36:54 yS0    US Robotics: VI: input:  4
08/12 01:36:54 yS0  vgetty: Modem did not echo the command
08/12 01:36:54 yS0    US Robotics: VI: output: 7
08/12 01:36:54 yS0    US Robotics: VR: <HELLO SHELL>
08/12 01:36:54 yS0    US Robotics: VS: <HELLO VOICE PROGRAM>
08/12 01:36:54 yS0    US Robotics: VR: <READY>
08/12 01:36:54 yS0    US Robotics: VS: <DEVICE DIALUP_LINE>
08/12 01:36:54 yS0    US Robotics: AT#VLS=0
08/12 01:36:54 yS0    US Robotics: OK
08/12 01:36:54 yS0   vgetty(1): READY
08/12 01:36:54 yS0    vgetty: Got pipe signal
08/12 01:36:54 yS0    vgetty: queued event SIGNAL_SIGPIPE at position 0005
08/12 01:36:54 yS0    vgetty: unqueued event SIGNAL_SIGPIPE at position 0005

08/12 01:36:54 yS0    vgetty: voice_handle_event got event SIGNAL_SIGPIPE
with data <_>
08/12 01:36:54 yS0   shell(1): PLAY /var/spool/voice/messages/welcome
08/12 01:36:54 yS0   vgetty(1): PLAYING
08/12 01:36:54 yS0  playing voice file /var/spool/voice/messages/welcome
08/12 01:36:54 yS0   vgetty: raw modem data header found
08/12 01:36:54 yS0   vgetty: modem type US Robotics found
08/12 01:36:54 yS0   vgetty: compression method 0x0001, speed 8000, bits 8
08/12 01:36:54 yS0    vgetty: queued event RESET_WATCHDOG at position 0006
08/12 01:36:54 yS0    vgetty: unqueued event RESET_WATCHDOG at position 0006

08/12 01:36:54 yS0    vgetty: voice_handle_event got event RESET_WATCHDOG
with data <_>
08/12 01:36:54 yS0   voice command: 'AT' -> 'OK'
08/12 01:36:54 yS0    vgetty: AT
08/12 01:36:54 yS0    US Robotics: VR: <READY>
08/12 01:36:54 yS0  vgetty: Modem did not echo the command
08/12 01:36:54 yS0    US Robotics: VS: <PLAY
/var/spool/voice/messages/welcome>
08/12 01:36:54 yS0    US Robotics: VR: <PLAYING>
08/12 01:36:55 yS0    US Robotics: AT
08/12 01:36:55 yS0    US Robotics: OK
08/12 01:36:55 yS0  vgetty: start_play_file command failed
08/12 01:36:55 yS0   vgetty(1): ERROR
08/12 01:36:55 yS0   vgetty(1): READY
08/12 01:36:55 yS0    vgetty: Got child changed status signal
08/12 01:36:55 yS0    vgetty: queued event SIGNAL_SIGCHLD at position 0007
08/12 01:36:55 yS0   vgetty: shell exited normally with status 0x001d
08/12 01:36:55 yS0    vgetty: queued event RESET_WATCHDOG at position 0008
08/12 01:36:55 yS0   voice command: 'AT#VLS=0H0' -> 'OK|VCON'
08/12 01:36:55 yS0    vgetty: AT#VLS=0H0
08/12 01:36:55 yS0    vgetty: unqueued event SIGNAL_SIGCHLD at position 0007

08/12 01:36:55 yS0    vgetty: voice_handle_event got event SIGNAL_SIGCHLD
with data <_>
08/12 01:36:55 yS0    vgetty: voice_handle_event got unknown event
SIGNAL_SIGCHLD with data <_>
08/12 01:36:55 yS0    vgetty: unqueued event RESET_WATCHDOG at position 0008

08/12 01:36:55 yS0    vgetty: voice_handle_event got event RESET_WATCHDOG
with data <_>
08/12 01:36:55 yS0    US Robotics: VR: <ERROR>
08/12 01:36:55 yS0  vgetty: Modem did not echo the command
08/12 01:36:55 yS0    US Robotics: /usr/local/bin/demo.pl: something went
wrong on playing (ERROR) at /usr/local/bin/demo.pl line 136, <GEN0> chunk 5.

08/12 01:36:55 yS0    US Robotics: AT#VLS=0H0
08/12 01:36:55 yS0    US Robotics: OK
08/12 01:36:55 yS0   vgetty: leaving voice mode
08/12 01:36:55 yS0   voice command: 'AT#CLS=2.0' -> 'OK'
08/12 01:36:55 yS0    vgetty: AT#CLS=2.0
08/12 01:36:55 yS0    US Robotics: AT#CLS=2.0
08/12 01:36:55 yS0    US Robotics: OK
08/12 01:36:55 yS0   voice command: 'AT' -> 'OK'
08/12 01:36:55 yS0    vgetty: AT
08/12 01:36:55 yS0    US Robotics: AT
08/12 01:36:56 yS0    US Robotics: OK
08/12 01:36:56 yS0   vgetty: Restoring signal handlers
08/12 01:36:56 yS0  closing voice modem device
08/12 01:36:56 yS0   removing lock file
------------------------------------------------------------------------------

Again, any help is appreciated, so TIA!

--
--Moe Pitman
Three-Sixteen Technical Services, Inc.
Linux Training in Austin, Texas!
http://training.three-sixteen.com/