BUSY after greeting playback
Dmitry Pogosyan (pogosyan@cita.utoronto.ca)
Sat, 5 Jun 1999 22:58:22 -0400
Hi,
I'm continue playing with my vgetty (it is still 1.1.19, sorry Gert
and Marc, have not yet found time to install the latest).
Here comes new puzzle. After all analysis earlier in May I had
finely working vgetty in voice/fax/data mode. The only thing missing
was greetings message. Finally I recordered it (in voc and converted to
rmd, I have Rockwell 4 bits/sample mode). It plays back O'K too.
But, here comes the glitch. Now when I try to log into my computer
from remote modem in data mode, I'd say 9 times out of 10 (but not 100%)
I get BUSY signal on my remote modem. I timed when does it happen, and
also listened carefully for the remote modem dialing.
BUSY appears immediately after greetings message is played, and
BEFORE the generated beep. Actually, there is no distinguishable
delay between the end of the message and BUSY received on remote modem
(certainly less than a second).
Of course I can resolve the situation if before dialing into my computer
from afar I set 'blind dialing', i.e ask to ignore BUSY signal.
Then everything works fine. But leaves a feeling of imperfection :)
I tried two different greetings (in case my daughter in the first
one emitted something on BUSY frequency :) ) but with the same result.
BTW, does somebody know what is BUSY frequency in North America ?
I could try filtering out this frequencey completely from my recording
to be sure ...
I included a log with marked region where remote modem detected BUSY.
But log looks perfectly O'K, of course further connection failed in due
course since remote modem already gave up by the time fax/data
negotiation took place.
Any ideas ? Oh yes, remote modem is USRobotics external (but which one ??,
looks like white soap box). My home modem is Rockwell based ZOOM.
Regards, Dmitri Pogosyan
---------------------------------------------------------------------------
Dmitri Pogosian 102 Aldwych Ave.
tel/fax: 1-416-466-4028 Toronto, ON M4J 1X6
e-mail: pogosyan@cita.utoronto.ca Canada
---------------------------------------------------------------------------
Here is the log:
06/05 17:29:57 yS3 waiting...
06/05 17:30:38 yS3 vgetty: number of rings (5) was set directly
06/05 17:30:38 yS3 vgetty: decremented number of rings (5) by 0
06/05 17:30:38 yS3 wfr: waiting for ``RING''
06/05 17:30:38 yS3 got: [0d][0a]RING[0d]
06/05 17:30:38 yS3 CND: RING
06/05 17:30:38 yS3 wfr: rc=0, drn=0
06/05 17:30:38 yS3 wfr: waiting for ``RING''
06/05 17:30:38 yS3 got: [0a][0d][0a]RING[0d]
06/05 17:30:44 yS3 CND: RING
06/05 17:30:44 yS3 wfr: rc=0, drn=0
06/05 17:30:44 yS3 wfr: waiting for ``RING''
06/05 17:30:44 yS3 got: [0a][0d][0a]RING[0d]
06/05 17:30:51 yS3 CND: RING
06/05 17:30:51 yS3 wfr: rc=0, drn=0
06/05 17:30:51 yS3 wfr: waiting for ``RING''
06/05 17:30:51 yS3 got: [0a][0d][0a]RING[0d]
06/05 17:30:57 yS3 CND: RING
06/05 17:30:57 yS3 wfr: rc=0, drn=0
06/05 17:30:57 yS3 wfr: waiting for ``RING''
06/05 17:30:57 yS3 got: [0a][0d][0a]RING[0d]
06/05 17:31:03 yS3 CND: RING
06/05 17:31:03 yS3 wfr: rc=0, drn=0
06/05 17:31:03 yS3 reading ring_type ring configuration from config file /etc/mgetty+sendfax/voice.conf
06/05 17:31:03 yS3 vgetty: answer mode was set directly
06/05 17:31:03 yS3 vgetty: answer mode is [data|fax|voice]
06/05 17:31:03 yS3 vgetty: opening list file /var/spool/voice/messages/Index
06/05 17:31:03 yS3 vgetty: found 1 messages, picked message number 1
06/05 17:31:03 yS3 vgetty: message name is /var/spool/voice/messages/greeting.rmd
06/05 17:31:03 yS3 vgetty: entering voice mode
06/05 17:31:03 yS3 vgetty: Installing signal handlers
06/05 17:31:03 yS3 voice command: 'AT#CLS?' -> ''
06/05 17:31:03 yS3 vgetty: AT#CLS?
06/05 17:31:03 yS3 Rockwell: 0
06/05 17:31:03 yS3 voice command: '' -> 'OK'
06/05 17:31:03 yS3 Rockwell: OK
06/05 17:31:03 yS3 voice command: 'AT#CLS=8' -> 'OK'
06/05 17:31:03 yS3 vgetty: AT#CLS=8
06/05 17:31:03 yS3 Rockwell: OK
06/05 17:31:03 yS3 voice command: 'AT' -> 'OK'
06/05 17:31:03 yS3 vgetty: AT
06/05 17:31:03 yS3 Rockwell: <DLE> <h>
06/05 17:31:03 yS3 vgetty: queued event HANDSET_ON_HOOK at position 0002
06/05 17:31:03 yS3 Rockwell:
06/05 17:31:03 yS3 Rockwell: OK
06/05 17:31:03 yS3 vgetty: queued event RESET_WATCHDOG at position 0003
06/05 17:31:03 yS3 voice command: 'AT#VLS=4' -> 'OK'
06/05 17:31:03 yS3 vgetty: AT#VLS=4
06/05 17:31:03 yS3 vgetty: unqueued event HANDSET_ON_HOOK at position 0002
06/05 17:31:03 yS3 vgetty: voice_handle_event got event HANDSET_ON_HOOK with data <
06/05 17:31:03 yS3 vgetty: unqueued event RESET_WATCHDOG at position 0003
06/05 17:31:03 yS3 vgetty: voice_handle_event got event RESET_WATCHDOG with data <
06/05 17:31:03 yS3 Rockwell: OK
06/05 17:31:03 yS3 voice command: 'ATA' -> 'VCON'
06/05 17:31:03 yS3 vgetty: ATA
06/05 17:31:03 yS3 Rockwell: VCON
06/05 17:31:05 yS3 playing voice file /var/spool/voice/messages/greeting.rmd
06/05 17:31:05 yS3 vgetty: raw modem data header found
06/05 17:31:05 yS3 vgetty: modem type Rockwell found
06/05 17:31:05 yS3 vgetty: compression method 0x0004, speed 7200, bits 4
06/05 17:31:05 yS3 vgetty: queued event RESET_WATCHDOG at position 0004
06/05 17:31:05 yS3 voice command: 'AT#VBS=4' -> 'OK'
06/05 17:31:05 yS3 vgetty: AT#VBS=4
06/05 17:31:05 yS3 vgetty: unqueued event RESET_WATCHDOG at position 0004
06/05 17:31:05 yS3 vgetty: voice_handle_event got event RESET_WATCHDOG with data <d>
06/05 17:31:05 yS3 Rockwell: OK
06/05 17:31:05 yS3 vgetty: queued event RESET_WATCHDOG at position 0005
06/05 17:31:05 yS3 vgetty: unqueued event RESET_WATCHDOG at position 0005
06/05 17:31:05 yS3 vgetty: voice_handle_event got event RESET_WATCHDOG with data <d>
06/05 17:31:05 yS3 voice command: 'AT&K3' -> 'OK'
06/05 17:31:05 yS3 vgetty: AT&K3
06/05 17:31:05 yS3 Rockwell: OK
06/05 17:31:05 yS3 tio_set_flow_control( HARD XON_OUT )
06/05 17:31:05 yS3 voice command: 'AT#VTX' -> 'CONNECT'
06/05 17:31:05 yS3 vgetty: AT#VTX
06/05 17:31:05 yS3 Rockwell: CONNECT
06/05 17:31:13 yS3 vgetty: <VOICE DATA 35030 bytes>
----- somewhere between here and next line calling modem gets BUSY signal ---
06/05 17:31:13 yS3 vgetty: queued event RESET_WATCHDOG at position 0006
06/05 17:31:13 yS3 vgetty: unqueued event RESET_WATCHDOG at position 0006
06/05 17:31:13 yS3 vgetty: voice_handle_event got event RESET_WATCHDOG with data <d>
06/05 17:31:13 yS3 vgetty: <STOP PLAY>
06/05 17:31:13 yS3 voice command: '' -> 'OK|VCON'
06/05 17:31:13 yS3 Rockwell: VCON
06/05 17:31:15 yS3 vgetty: queued event RESET_WATCHDOG at position 0007
---------------------------------------------------------------------------
06/05 17:31:15 yS3 voice command: 'AT#VTS=[933,0,15]' -> ''
06/05 17:31:15 yS3 vgetty: AT#VTS=[933,0,15]
06/05 17:31:15 yS3 vgetty: unqueued event RESET_WATCHDOG at position 0007
06/05 17:31:15 yS3 vgetty: voice_handle_event got event RESET_WATCHDOG with data <
06/05 17:31:16 yS3 voice command: '' -> 'OK'
06/05 17:31:16 yS3 Rockwell: OK
06/05 17:31:17 yS3 recording voice file /var/spool/voice/incoming/va13646.rmd
06/05 17:31:17 yS3 vgetty: queued event RESET_WATCHDOG at position 0008
06/05 17:31:17 yS3 voice command: 'AT#VBS=2' -> 'OK'
06/05 17:31:17 yS3 vgetty: AT#VBS=2
06/05 17:31:17 yS3 vgetty: unqueued event RESET_WATCHDOG at position 0008
06/05 17:31:17 yS3 vgetty: voice_handle_event got event RESET_WATCHDOG with data <d>
06/05 17:31:17 yS3 Rockwell: OK
06/05 17:31:17 yS3 vgetty: queued event RESET_WATCHDOG at position 0009
06/05 17:31:17 yS3 vgetty: unqueued event RESET_WATCHDOG at position 0009
06/05 17:31:17 yS3 vgetty: voice_handle_event got event RESET_WATCHDOG with data <d>
06/05 17:31:17 yS3 voice command: 'AT&K3' -> 'OK'
06/05 17:31:17 yS3 vgetty: AT&K3
06/05 17:31:17 yS3 Rockwell: OK
06/05 17:31:17 yS3 tio_set_flow_control( HARD XON_IN )
06/05 17:31:17 yS3 voice command: 'AT#VRX' -> 'CONNECT'
06/05 17:31:17 yS3 vgetty: AT#VRX
06/05 17:31:17 yS3 Rockwell: CONNECT
06/05 17:31:24 yS3 Rockwell: <DLE> <s>
06/05 17:31:24 yS3 vgetty: queued event NO_VOICE_ENERGY at position 0010
06/05 17:31:24 yS3 vgetty: unqueued event NO_VOICE_ENERGY at position 0010
06/05 17:31:24 yS3 vgetty: voice_handle_event got event NO_VOICE_ENERGY with data <d>
06/05 17:31:24 yS3 vgetty: <STOP RECORDING>
06/05 17:31:24 yS3 Rockwell: <VOICE DATA 12436 bytes>
06/05 17:31:24 yS3 Rockwell: <DLE> <ETX>
06/05 17:31:24 yS3 voice command: '' -> 'OK|VCON'
06/05 17:31:24 yS3 Rockwell: VCON
06/05 17:31:24 yS3 vgetty: removing message /var/spool/voice/incoming/va13646.rmd
06/05 17:31:24 yS3 vgetty: trying data and fax connection
06/05 17:31:24 yS3 voice command: 'AT#CLS=0' -> 'OK'
06/05 17:31:24 yS3 vgetty: AT#CLS=0
06/05 17:31:24 yS3 Rockwell: OK
06/05 17:31:25 yS3 voice command: 'AT' -> 'OK'
06/05 17:31:25 yS3 vgetty: AT
06/05 17:31:25 yS3 Rockwell: OK
06/05 17:31:25 yS3 voice command: 'AT+FAA=1;+FCR=1' -> 'OK'
06/05 17:31:25 yS3 vgetty: AT+FAA=1;+FCR=1
06/05 17:31:25 yS3 Rockwell: OK
06/05 17:31:25 yS3 vgetty: Restoring signal handlers
06/05 17:31:25 yS3 mdm_send: 'AT+FBOR=0'
06/05 17:31:25 yS3 got:[0a][0d][0a]OK[0d]
06/05 17:31:25 yS3 mdm_command: string 'OK' -> OK
06/05 17:31:25 yS3 send: ATA[0d]
06/05 17:31:25 yS3 waiting for ``CONNECT''
06/05 17:31:25 yS3 got: [0d]
06/05 17:32:23 yS3 CND: OK[0a]NO CARRIER
06/05 17:32:23 yS3 found action string: ``NO CARRIER''
06/05 17:32:23 ##### failed A_FAIL dev=ttyS3, pid=13646, caller='none',
conn='', name=''