vgetty interferes with ppp connection???

meunier@idiom.com (meunier@idiom.com)
Fri, 3 Oct 1997 07:36:08 +0200
Messages sorted by:[ date ][ thread ][ subject ][ author ]
I have a very strange problem. With vgetty up and running, my dialout
consistently fails during protocol/speed negotiation. But if I run mgetty
instead, I can dialout without a problem. Except for the voice
initialization sequence, the mgetty and vgetty log output look reasonably
the same. I am including the vgetty log output, and my /var/log/messages
output for the pppd/chat session.

What does vgetty do differently that would interfere with dialouts?

Any help debugging this will be much appreciated.

Thanks,

Roger
------------------------------- >8 cut 8< -------------------------------------
10/02 22:12:24 dem vgetty: experimental test release 0.7.2 / 12Apr97
10/02 22:12:24 dem mgetty: experimental test release 1.1.8-Jul27
10/02 22:12:24 dem reading generic configuration from config file /etc/mgetty+sendfax/voice.conf
10/02 22:12:24 dem reading program vgetty configuration from config file /etc/mgetty+sendfax/voice.conf
10/02 22:12:24 dem reading port modem configuration from config file /etc/mgetty+sendfax/voice.conf
10/02 22:12:24 dem reading /etc/mgetty+sendfax/voice.conf...
10/02 22:12:24 dem conf lib: read: 'part generic'
10/02 22:12:24 dem found CT_KEYWORD part generic
10/02 22:12:24 dem conf lib: read: 'voice_log_level 6'
10/02 22:12:24 dem conf lib: read: 'voice_dir /var/spool/voice'
10/02 22:12:24 dem conf lib: read: 'message_flag_file .flag'
10/02 22:12:24 dem conf lib: read: 'receive_dir incoming'
10/02 22:12:24 dem conf lib: read: 'message_dir messages'
10/02 22:12:24 dem conf lib: read: 'message_list Index'
10/02 22:12:24 dem conf lib: read: 'backup_message standard.rmd'
10/02 22:12:24 dem conf lib: read: 'port_speed 38400'
10/02 22:12:24 dem conf lib: read: 'voice_shell /bin/sh'
10/02 22:12:24 dem conf lib: read: 'port_timeout 10'
10/02 22:12:24 dem conf lib: read: 'dial_timeout 90'
10/02 22:12:24 dem conf lib: read: 'command_delay 100'
10/02 22:12:24 dem conf lib: read: 'dtmf_len 30'
10/02 22:12:24 dem conf lib: read: 'dtmf_threshold 40'
10/02 22:12:24 dem conf lib: read: 'dtmf_wait 7'
10/02 22:12:24 dem conf lib: read: 'ignore_fax_dle false'
10/02 22:12:24 dem conf lib: read: 'raw_data false'
10/02 22:12:24 dem conf lib: read: 'rec_compression 0'
10/02 22:12:24 dem conf lib: read: 'rec_speed 0'
10/02 22:12:24 dem conf lib: read: 'rec_silence_len 70'
10/02 22:12:24 dem conf lib: read: 'rec_silence_threshold 40'
10/02 22:12:24 dem conf lib: read: 'rec_remove_silence false'
10/02 22:12:24 dem conf lib: read: 'rec_max_len 300'
10/02 22:12:24 dem conf lib: read: 'rec_min_len 0'
10/02 22:12:24 dem conf lib: read: 'do_hard_flow true'
10/02 22:12:24 dem conf lib: read: 'beep_frequency 933'
10/02 22:12:24 dem conf lib: read: 'beep_length 150'
10/02 22:12:24 dem conf lib: read: 'max_tries 3'
10/02 22:12:24 dem conf lib: read: 'retry_delay 5'
10/02 22:12:24 dem conf lib: read: 'watchdog_timeout 60'
10/02 22:12:24 dem conf lib: read: 'receive_gain -1'
10/02 22:12:24 dem conf lib: read: 'transmit_gain -1'
10/02 22:12:24 dem conf lib: read: 'enable_command_echo true'
10/02 22:12:24 dem conf lib: read: 'program vgetty'
10/02 22:12:24 dem conf lib: read: 'voice_devices modem'
10/02 22:12:24 dem conf lib: read: 'ring_type ring'
10/02 22:12:24 dem conf lib: read: 'rings 2'
10/02 22:12:24 dem conf lib: read: 'answer_mode voice:fax:data'
10/02 22:12:24 dem conf lib: read: 'force_autodetect false'
10/02 22:12:24 dem conf lib: read: 'toll_saver_rings 0'
10/02 22:12:24 dem conf lib: read: 'rec_always_keep true'
10/02 22:12:24 dem conf lib: read: 'button_program '
10/02 22:12:24 dem conf lib: read: 'call_program '
10/02 22:12:24 dem conf lib: read: 'dtmf_program dtmf.sh'
10/02 22:12:24 dem conf lib: read: 'message_program '
10/02 22:12:24 dem conf lib: read: 'do_message_light false'
10/02 22:12:24 dem conf lib: read: 'program vm'
10/02 22:12:24 dem conf lib: read: 'voice_devices modem'
10/02 22:12:24 dem conf lib: read: 'dialout_timeout 90'
10/02 22:12:24 dem conf lib: read: 'program pvf'
10/02 22:12:24 dem key: 'part', type=6, flags=4, data=(ignored)
10/02 22:12:24 dem key: 'program', type=6, flags=4, data=(ignored)
10/02 22:12:24 dem key: 'port', type=6, flags=4, data=(ignored)
10/02 22:12:24 dem key: 'ring_type', type=6, flags=4, data=(ignored)
10/02 22:12:24 dem key: 'voice_log_level', type=0, flags=3, data=6
10/02 22:12:24 dem key: 'voice_devices', type=1, flags=3, data=modem
10/02 22:12:24 dem key: 'port_speed', type=0, flags=3, data=38400
10/02 22:12:24 dem key: 'port_timeout', type=0, flags=3, data=10
10/02 22:12:24 dem key: 'dtmf_len', type=0, flags=3, data=30
10/02 22:12:24 dem key: 'dtmf_threshold', type=0, flags=3, data=40
10/02 22:12:24 dem key: 'dtmf_wait', type=0, flags=3, data=7
10/02 22:12:24 dem key: 'rec_compression', type=0, flags=3, data=0
10/02 22:12:24 dem key: 'rec_speed', type=0, flags=3, data=0
10/02 22:12:24 dem key: 'rec_silence_len', type=0, flags=3, data=70
10/02 22:12:24 dem key: 'rec_silence_threshold', type=0, flags=3, data=40
10/02 22:12:24 dem key: 'rec_remove_silence', type=3, flags=3, data=FALSE
10/02 22:12:24 dem key: 'rec_max_len', type=0, flags=3, data=300
10/02 22:12:24 dem key: 'receive_gain', type=0, flags=3, data=-1
10/02 22:12:24 dem key: 'transmit_gain', type=0, flags=3, data=-1
10/02 22:12:24 dem key: 'rings', type=1, flags=1, data=3
10/02 22:12:24 dem key: 'answer_mode', type=1, flags=1, data=voice:fax:data
10/02 22:12:24 dem key: 'toll_saver_rings', type=0, flags=1, data=0
10/02 22:12:24 dem key: 'rec_always_keep', type=3, flags=1, data=TRUE
10/02 22:12:24 dem key: 'voice_dir', type=1, flags=3, data=/var/spool/voice
10/02 22:12:24 dem key: 'message_flag_file', type=1, flags=3, data=.flag
10/02 22:12:24 dem key: 'receive_dir', type=1, flags=3, data=incoming
10/02 22:12:24 dem key: 'message_dir', type=1, flags=3, data=messages
10/02 22:12:24 dem key: 'message_list', type=1, flags=3, data=Index
10/02 22:12:24 dem key: 'backup_message', type=1, flags=3, data=standard.rmd
10/02 22:12:24 dem key: 'dialout_timeout', type=0, flags=1, data=90
10/02 22:12:24 dem key: 'beep_frequency', type=0, flags=3, data=933
10/02 22:12:24 dem key: 'beep_length', type=0, flags=3, data=150
10/02 22:12:24 dem key: 'raw_data', type=3, flags=3, data=FALSE
10/02 22:12:24 dem key: 'max_tries', type=0, flags=3, data=3
10/02 22:12:24 dem key: 'retry_delay', type=0, flags=3, data=5
10/02 22:12:24 dem key: 'voice_shell', type=1, flags=3, data=/bin/sh
10/02 22:12:24 dem key: 'button_program', type=1, flags=1, data=
10/02 22:12:24 dem key: 'call_program', type=1, flags=1, data=
10/02 22:12:24 dem key: 'dtmf_program', type=1, flags=1, data=dtmf.sh
10/02 22:12:24 dem key: 'message_program', type=1, flags=1, data=
10/02 22:12:24 dem key: 'do_message_light', type=3, flags=1, data=FALSE
10/02 22:12:24 dem key: 'do_hard_flow', type=3, flags=3, data=TRUE
10/02 22:12:24 dem key: 'force_autodetect', type=3, flags=1, data=FALSE
10/02 22:12:24 dem key: 'watchdog_timeout', type=0, flags=3, data=60
10/02 22:12:24 dem key: 'rec_min_len', type=0, flags=3, data=0
10/02 22:12:24 dem key: 'command_delay', type=0, flags=3, data=100
10/02 22:12:24 dem key: 'ignore_fax_dle', type=3, flags=3, data=FALSE
10/02 22:12:24 dem key: 'dial_timeout', type=0, flags=3, data=90
10/02 22:12:24 dem key: 'enable_command_echo', type=3, flags=3, data=TRUE
10/02 22:12:24 dem check for lockfiles
10/02 22:12:24 dem checklock: stat failed, no file
10/02 22:12:24 dem locking the line
10/02 22:12:24 dem makelock(modem) called
10/02 22:12:24 dem do_makelock: lock='/var/lock/LCK..modem'
10/02 22:12:24 dem lock made
10/02 22:12:25 dem tio_get_rs232_lines: status: RTS CTS DSR DTR
10/02 22:12:25 dem lowering DTR to reset Modem
10/02 22:12:25 dem tss: set speed to 38400 (017)
10/02 22:12:25 dem tio_set_flow_control( HARD )
10/02 22:12:25 dem waiting for line to clear (VTIME), read: 
10/02 22:12:25 dem send: \dATQ0V1H0[0d]
10/02 22:12:26 dem waiting for ``OK''
10/02 22:12:26 dem got: [0d][0a]OK ** found **
10/02 22:12:26 dem send: ATS0=0Q0&D3&C1[0d]
10/02 22:12:26 dem waiting for ``OK''
10/02 22:12:26 dem got: [0d]
10/02 22:12:26 dem CND: OK[0a][0d][0a]OK ** found **
10/02 22:12:26 dem mdm_send: 'ATI'
10/02 22:12:26 dem got:[0d][0a][0d][0a]56000[0d]
10/02 22:12:26 dem mdm_gis: string 1: '56000'
10/02 22:12:26 dem got:[0a][0d][0a]OK[0d]
10/02 22:12:26 dem mdm_identify: string '56000'
10/02 22:12:26 dem Generic Rockwell modem (56000)
10/02 22:12:26 dem mdm_send: 'ATI4'
10/02 22:12:26 dem got:[0a][0d][0a]Motorola VoiceSURFR 56K External[0d]
10/02 22:12:26 dem mdm_gis: string 1: 'Motorola VoiceSURFR 56K External'
10/02 22:12:26 dem got:[0a][0d][0a]OK[0d]
10/02 22:12:26 dem additional info: 'Motorola VoiceSURFR 56K External'
10/02 22:12:26 dem mdm_send: 'AT+FCLASS=1'
10/02 22:12:26 dem got:[0a][0d][0a]OK[0d]
10/02 22:12:26 dem mdm_command: string 'OK' -> OK
10/02 22:12:26 dem mdm_send: 'AT+FCLASS=1'
10/02 22:12:26 dem got:[0a][0d][0a]OK[0d]
10/02 22:12:26 dem mdm_command: string 'OK' -> OK
10/02 22:12:26 dem tss: set speed to 38400 (017)
10/02 22:12:26 dem tio_set_flow_control( HARD )
10/02 22:12:26 dem detecting voice modem type
10/02 22:12:26 dem vgetty: ATE1
10/02 22:12:26 dem voice command: '' -> 'OK|ATE1'
10/02 22:12:26 dem serial port: OK
10/02 22:12:26 dem voice command: 'ATI' -> ''
10/02 22:12:26 dem vgetty: ATI
10/02 22:12:26 dem serial port: ATI
10/02 22:12:26 dem serial port: 56000
10/02 22:12:26 dem Rockwell: OK
10/02 22:12:27 dem Rockwell detected
10/02 22:12:27 dem vgetty: queued event 0x4000 at position 0000
10/02 22:12:27 dem initializing ROCKWELL voice modem
10/02 22:12:27 dem vgetty: queued event 0x4000 at position 0001
10/02 22:12:27 dem voice command: 'AT#CLS?' -> ''
10/02 22:12:27 dem vgetty: AT#CLS?
10/02 22:12:27 dem Rockwell: AT#CLS?
10/02 22:12:27 dem Rockwell: 1
10/02 22:12:27 dem voice command: '' -> 'OK'
10/02 22:12:27 dem Rockwell: OK
10/02 22:12:27 dem voice command: 'AT#CLS=8' -> 'OK'
10/02 22:12:27 dem vgetty: AT#CLS=8
10/02 22:12:27 dem Rockwell: AT#CLS=8
10/02 22:12:29 dem Rockwell: OK
10/02 22:12:29 dem voice command: 'AT#VSP=70' -> 'OK'
10/02 22:12:29 dem vgetty: AT#VSP=70
10/02 22:12:29 dem Rockwell: <DLE> <h>
10/02 22:12:29 dem vgetty: queued event 0x2007 at position 0002
10/02 22:12:29 dem Rockwell: 
10/02 22:12:29 dem Rockwell: AT#VSP=70
10/02 22:12:29 dem Rockwell: OK
10/02 22:12:29 dem voice command: 'AT#VSD=0' -> 'OK'
10/02 22:12:29 dem vgetty: AT#VSD=0
10/02 22:12:29 dem Rockwell: AT#VSD=0
10/02 22:12:29 dem Rockwell: OK
10/02 22:12:29 dem voice command: 'AT#VTD=3F,3F,3F' -> 'OK'
10/02 22:12:29 dem vgetty: AT#VTD=3F,3F,3F
10/02 22:12:29 dem Rockwell: AT#VTD=3F,3F,3F
10/02 22:12:29 dem Rockwell: OK
10/02 22:12:29 dem voice command: 'AT#VSS=1' -> 'OK'
10/02 22:12:29 dem vgetty: AT#VSS=1
10/02 22:12:29 dem Rockwell: AT#VSS=1
10/02 22:12:29 dem Rockwell: OK
10/02 22:12:29 dem vgetty: queued event 0x4000 at position 0003
10/02 22:12:29 dem voice command: 'AT#CLS=1' -> 'OK'
10/02 22:12:29 dem vgetty: AT#CLS=1
10/02 22:12:29 dem Rockwell: AT#CLS=1
10/02 22:12:29 dem Rockwell: OK
10/02 22:12:29 dem voice command: 'AT&K3' -> 'OK'
10/02 22:12:30 dem vgetty: AT&K3
10/02 22:12:30 dem Rockwell: AT&K3
10/02 22:12:30 dem Rockwell: OK
10/02 22:12:30 dem tio_set_flow_control( HARD )
10/02 22:12:30 dem waiting for line to clear (VTIME), read: 
10/02 22:12:30 dem removing lock file
10/02 22:12:30 dem waiting...
10/02 22:13:53 dem select returned 1
10/02 22:13:53 dem checking lockfiles, locking the line
10/02 22:13:53 dem makelock(modem) called
10/02 22:13:53 dem do_makelock: lock='/var/lock/LCK..modem'
10/02 22:13:53 dem lock not made: lock file exists (pid=6681)
10/02 22:13:53 dem lock file exists (dialout)!
10/02 22:13:53 dem lockfile found, pid=6681
10/02 22:13:53 dem looking for utmp entry... (my PID: 6658)
10/02 22:13:53 dem utmp + wtmp entry made
10/02 22:13:53 dem lockfile found, pid=6681
10/02 22:14:03 dem lockfile found, pid=6681
10/02 22:14:13 dem lockfile found, pid=6681
10/02 22:14:23 dem lockfile found, pid=6681
10/02 22:14:33 dem checklock: stat failed, no file
10/02 22:14:38 dem checklock: stat failed, no file
------------------------------- >8 cut 8< -------------------------------------
Oct 2 22:13:52 meunier ifup-ppp: pppd started for ppp0 on /dev/modem at 57600
Oct 2 22:13:52 meunier kernel: PPP: version 2.2.0 (dynamic channel allocation)
Oct 2 22:13:52 meunier kernel: PPP Dynamic channel allocation code copyright 1995 Caldera, Inc.
Oct 2 22:13:52 meunier kernel: PPP line discipline registered.
Oct 2 22:13:52 meunier kernel: registered device ppp0
Oct 2 22:13:52 meunier pppd[6681]: pppd 2.2.0 started by roger, uid 500
Oct 2 22:13:53 meunier chat[6685]: abort on (BUSY) 
Oct 2 22:13:53 meunier chat[6685]: abort on (ERROR) 
Oct 2 22:13:53 meunier chat[6685]: abort on (NO CARRIER) 
Oct 2 22:13:53 meunier chat[6685]: abort on (NO DIALTONE) 
Oct 2 22:13:53 meunier chat[6685]: abort on (Invalid Login) 
Oct 2 22:13:53 meunier chat[6685]: abort on (Login incorrect) 
Oct 2 22:13:53 meunier chat[6685]: timeout set to 5 seconds
Oct 2 22:13:53 meunier chat[6685]: send (AT&F0&C1&D2&K3\\V1\\N3L1S0=0s202=32V1Q0M1E0^M) 
Oct 2 22:13:54 meunier chat[6685]: expect (OK) 
Oct 2 22:13:54 meunier chat[6685]: AT&F0&C1&D2&K3\V1\N3L1S0=0s202=32V1Q0M1E0^M^M 
Oct 2 22:13:54 meunier chat[6685]: OK -- got it 
Oct 2 22:13:54 meunier chat[6685]: send (ATDT3970026^M) 
Oct 2 22:13:54 meunier chat[6685]: timeout set to 30 seconds
Oct 2 22:13:54 meunier chat[6685]: expect (CONNECT) 
Oct 2 22:13:54 meunier chat[6685]: ^M 
Oct 2 22:14:24 meunier chat[6685]: alarm
Oct 2 22:14:24 meunier chat[6685]: Failed
Oct 2 22:14:24 meunier pppd[6681]: Connect script failed
Oct 2 22:14:24 meunier pppd[6681]: Exit.
----------------
Roger Meunier	email: meunier@idiom.com "The Lord is my Shepherd..."
.