Attachment 150181 Details for Bug 232522 – mgetty log at debug level 6 showing where external program is called too soon.

mgetty log at debug level 6 showing where external program is called too soon.

mgetty.log.txt (text/plain), 9.16 KB, created by Don Russell on 2007-03-15 22:57:34 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Don Russell

Created: 2007-03-15 22:57:34 UTC

Size: 9.16 KB

patch

obsolete

>--
>03/15 12:51:44 yS1  mgetty: interim release 1.1.33-Apr10
>03/15 12:51:45 yS1  check for lockfiles
>03/15 12:51:45 yS1   checklock: stat failed, no file
>03/15 12:51:45 yS1  locking the line
>03/15 12:51:45 yS1   makelock(ttyS1) called
>03/15 12:51:45 yS1   do_makelock: lock='/var/lock/LCK..ttyS1'
>03/15 12:51:45 yS1   lock made
>03/15 12:51:45 yS1   tio_get_rs232_lines: status: RTS CTS DSR DTR
>03/15 12:51:45 yS1  lowering DTR to reset Modem
>03/15 12:51:46 yS1   tss: set speed to 19200 (016)
>03/15 12:51:46 yS1   tio_set_flow_control( HARD )
>03/15 12:51:46 yS1   waiting for line to clear (VTIME=1), read: 
>03/15 12:51:46 yS1  send: ATI7[0d]
>03/15 12:51:46 yS1  waiting for ``OK''
>03/15 12:51:46 yS1   got: [0d][0a]USRobotics Courier V.Everything Configuration Profile...[0d]
>03/15 12:51:46 yS1    CND: USRobotics Courier V.Everything Configuration Profile...[0a][0d][0a]Product type           US/Canada External[0d]
>03/15 12:51:46 yS1    CND: Product type           US/Canada External[0a]Options                HST,V32bis,Terbo,VFC,V34+,x2,V90[0d]
>03/15 12:51:46 yS1    CND: Options                HST,V32bis,Terbo,VFC,V34+,x2,V90[0a]Fax Options            Class 1,Class 2.0[0d]
>03/15 12:51:46 yS1    CND: Fax Options            Class 1,Class 2.0[0a]Clock Freq             25 Mhz[0d]
>03/15 12:51:46 yS1    CND: Clock Freq             25 Mhz[0a]Flash ROM              512k[0d]
>03/15 12:51:46 yS1    CND: Flash ROM              512k[0a]Ram                    64k[0d]
>03/15 12:51:46 yS1    CND: Ram                    64k[0a][0d][0a]Supervisor date        03/13/98[0d]
>03/15 12:51:46 yS1    CND: Supervisor date        03/13/98[0a]DSP date               03/13/98[0d]
>03/15 12:51:46 yS1    CND: DSP date               03/13/98[0a][0d][0a]Supervisor rev         7.3.14[0d]
>03/15 12:51:46 yS1    CND: Supervisor rev         7.3.14[0a]DSP rev                3.0.13[0d]
>03/15 12:51:46 yS1    CND: DSP rev                3.0.13[0a][0d][0a]Serial Number          328xxxxxxxxx[0d]
>03/15 12:51:46 yS1    CND: Serial Number          328xxxxxxxxx[0a][0d][0a]OK ** found **
>03/15 12:51:46 yS1  send: AT&F1[0d]
>03/15 12:51:46 yS1  waiting for ``OK''
>03/15 12:51:46 yS1   got: [0d]
>03/15 12:51:46 yS1    CND: OK[0a][0d][0a]OK ** found **
>03/15 12:51:46 yS1  send: ATS0=255S7=3M0#CID=1[0d]
>03/15 12:51:46 yS1  waiting for ``OK''
>03/15 12:51:46 yS1   got: [0d]
>03/15 12:51:46 yS1    CND: OK[0a][0d][0a]OK ** found **
>03/15 12:51:47 yS1  send: ATI4[0d]
>03/15 12:51:47 yS1  waiting for ``OK''
>03/15 12:51:47 yS1   got: [0d]
>03/15 12:51:47 yS1    CND: OK[0a][0d][0a]USRobotics Courier V.Everything Settings...[0d]
>03/15 12:51:47 yS1    CND: USRobotics Courier V.Everything Settings...[0a][0d][0a]   B0  C1  E0  F1  M0  Q0  V1  X7[0d]
>03/15 12:51:47 yS1    CND: B0  C1  E0  F1  M0  Q0  V1  X7[0a]   BAUD=19200  PARITY=N  WORDLEN=8[0d]
>03/15 12:51:47 yS1    CND: BAUD=19200  PARITY=N  WORDLEN=8[0a]   DIAL=PULSE  ON HOOK ** found **
>03/15 12:51:47 yS1  mdm_send: 'ATI'
>03/15 12:51:47 yS1    got:   TIMER[0d]
>03/15 12:51:47 yS1   mdm_gis: string 1: '   TIMER'
>03/15 12:51:47 yS1    got:[0a][0d][0a]   &A3  &B1  &C1  &D2  &G0  &H1  &I0  &K1  &L0  &M4  &N0[0d]
>03/15 12:51:47 yS1   mdm_gis: string 2: '   &A3  &B1  &C1  &D2  &G0  &H1  &I0  &K1  &L0  &M4  &N0'
>03/15 12:51:47 yS1    got:[0a]   &P0  &R2  &S0  &T5  &U0  &X0  &Y1  %N6  #CID=1  [0d]
>03/15 12:51:47 yS1   mdm_gis: string 3: '   &P0  &R2  &S0  &T5  &U0  &X0  &Y1  %N6  #CID=1  '
>03/15 12:51:47 yS1    got:[0a][0d][0a]   S00=255  S01=000  S02=043  S03=013  S04=010  S05=008  S06=002  S07=003  [0d]
>03/15 12:51:47 yS1   mdm_gis: string 4: '   S00=255  S01=000  S02=043  S03=013  S04=010  S05=008  S06=002  S07=003  '
>03/15 12:51:47 yS1    got:[0a]   S08=002  S09=006  S10=014  S11=070  S12=050  S13=000  S14=001  S15=000  [0d]
>03/15 12:51:47 yS1   mdm_gis: string 5: '   S08=002  S09=006  S10=014  S11=070  S12=050  S13=000  S14=001  S15=000  '
>03/15 12:51:47 yS1    got:[0a]   S16=000  S17=000  S18=000  S19=000  S20=000  S21=010  S22=017  S23=019  [0d]
>03/15 12:51:47 yS1   mdm_gis: string 6: '   S16=000  S17=000  S18=000  S19=000  S20=000  S21=010  S22=017  S23=019  '
>03/15 12:51:47 yS1    got:[0a]   S24=150  S25=005  S26=001  S27=000  S28=008  S29=020  S30=000  S31=000  [0d]
>03/15 12:51:47 yS1   mdm_gis: string 7: '   S24=150  S25=005  S26=001  S27=000  S28=008  S29=020  S30=000  S31=000  '
>03/15 12:51:47 yS1    got:[0a]   S32=009  S33=000  S34=000  S35=000  S36=000  S37=000  S38=000  S39=000  [0d]
>03/15 12:51:47 yS1   mdm_gis: string 8: '   S32=009  S33=000  S34=000  S35=000  S36=000  S37=000  S38=000  S39=000  '
>03/15 12:51:47 yS1    got:[0a]   S40=000  S41=000  S42=126  S43=200  S44=015  S45=000  S46=000  S47=000  [0d]
>03/15 12:51:47 yS1   mdm_gis: string 9: '   S40=000  S41=000  S42=126  S43=200  S44=015  S45=000  S46=000  S47=000  '
>03/15 12:51:47 yS1    got:[0a]   S48=000  S49=000  S50=000  S51=000  S52=000  S53=000  S54=064  S55=000  [0d]
>03/15 12:51:47 yS1   mdm_gis: string 10: '   S48=000  S49=000  S50=000  S51=000  S52=000  S53=000  S54=064  S55=000  '
>03/15 12:51:47 yS1    got:[0a]   S56=000  S57=000  S58=000  S59=000  S60=000  S61=000  S62=000  S63=000  [0d]
>03/15 12:51:47 yS1   mdm_gis: string 11: '   S56=000  S57=000  S58=000  S59=000  S60=000  S61=000  S62=000  S63=000  '
>03/15 12:51:47 yS1    got:[0a]   S64=000  S65=000  S66=000  S67=000  S68=000  S69=000  S70=000  [0d]
>03/15 12:51:47 yS1   mdm_gis: string 12: '   S64=000  S65=000  S66=000  S67=000  S68=000  S69=000  S70=000  '
>03/15 12:51:47 yS1    got:[0a][0d][0a]   LAST DIALED #:                                       [0d]
>03/15 12:51:47 yS1   mdm_gis: string 13: '   LAST DIALED #:                                       '
>03/15 12:51:47 yS1    got:[0a][0d][0a]OK[0d]
>03/15 12:51:47 yS1   mdm_identify: string '   TIMER'
>03/15 12:51:47 yS1  non-numeric ID string: '   TIMER'
>03/15 12:51:47 yS1  mdm_send: 'AT+FCLASS=2.0'
>03/15 12:51:47 yS1    got:[0a][0d][0a]OK[0d]
>03/15 12:51:47 yS1   mdm_command: string 'OK' -> OK
>03/15 12:51:48 yS1  mdm_send: 'AT+FAA=1;+FCR=1'
>03/15 12:51:48 yS1    got:[0a][0d][0a]OK[0d]
>03/15 12:51:48 yS1   mdm_command: string 'OK' -> OK
>03/15 12:51:48 yS1  mdm_send: 'AT+FBO=1'
>03/15 12:51:48 yS1    got:[0a][0d][0a]OK[0d]
>03/15 12:51:48 yS1   mdm_command: string 'OK' -> OK
>03/15 12:51:48 yS1  mdm_send: 'AT+FNR=1,1,1,0'
>03/15 12:51:48 yS1    got:[0a][0d][0a]OK[0d]
>03/15 12:51:48 yS1   mdm_command: string 'OK' -> OK
>03/15 12:51:48 yS1  mdm_send: 'AT+FLI="49 115 xxxxxxxx"'
>03/15 12:51:48 yS1    got:[0a][0d][0a]OK[0d]
>03/15 12:51:48 yS1   mdm_command: string 'OK' -> OK
>03/15 12:51:48 yS1  mdm_send: 'AT+FCC=1,5,0,2,0,0,0,0'
>03/15 12:51:48 yS1    got:[0a][0d][0a]OK[0d]
>03/15 12:51:48 yS1   mdm_command: string 'OK' -> OK
>03/15 12:51:48 yS1   waiting for line to clear (VTIME=3), read: 
>03/15 12:51:48 yS1   removing lock file
>03/15 12:51:48 yS1  waiting...
>03/15 13:51:48 yS1    select returned 0
>03/15 13:51:48 yS1  checking if modem is still alive
>03/15 13:51:48 yS1   makelock(ttyS1) called
>03/15 13:51:48 yS1   do_makelock: lock='/var/lock/LCK..ttyS1'
>03/15 13:51:48 yS1   lock made
>03/15 13:51:48 yS1  mdm_send: 'AT'
>03/15 13:51:48 yS1    got:[0a][0d][0a]OK[0d]
>03/15 13:51:48 yS1   mdm_command: string 'OK' -> OK
>03/15 13:51:48 yS1   waiting for line to clear (VTIME=3), read: 
>03/15 13:51:48 yS1   removing lock file
>03/15 13:51:48 yS1  waiting...
>03/15 14:51:48 yS1    select returned 0
>03/15 14:51:48 yS1  checking if modem is still alive
>03/15 14:51:48 yS1   makelock(ttyS1) called
>03/15 14:51:48 yS1   do_makelock: lock='/var/lock/LCK..ttyS1'
>03/15 14:51:48 yS1   lock made
>03/15 14:51:48 yS1  mdm_send: 'AT'
>03/15 14:51:48 yS1    got:[0a][0d][0a]OK[0d]
>03/15 14:51:48 yS1   mdm_command: string 'OK' -> OK
>03/15 14:51:48 yS1   waiting for line to clear (VTIME=3), read: 
>03/15 14:51:48 yS1   removing lock file
>03/15 14:51:48 yS1  waiting...
>03/15 15:08:06 yS1    select returned 1
>03/15 15:08:06 yS1   checking lockfiles, locking the line
>03/15 15:08:06 yS1   makelock(ttyS1) called
>03/15 15:08:06 yS1   do_makelock: lock='/var/lock/LCK..ttyS1'
>03/15 15:08:06 yS1   lock made
>03/15 15:08:06 yS1  wfr: waiting for ``RING''
>03/15 15:08:06 yS1   got: [0a][0d][0a]RING[0d]
>03/15 15:08:06 yS1    CND: RING
>03/15 15:08:06 yS1   wfr: rc=0, drn=0
>03/15 15:08:06 yS1  wfr: waiting for ``RING''
>03/15 15:08:06 yS1   got: [0a][0d][0a]DATE = 0315[0d]
>03/15 15:08:07 yS1    CND: DATE = 0315
>03/15 15:08:07 yS1    CND: found: 0315
>03/15 15:08:07 yS1   got: [0a]TIME = 1508[0d]
>03/15 15:08:07 yS1    CND: TIME = 1508
>03/15 15:08:07 yS1    CND: found: 1508
>03/15 15:08:07 yS1   got: [0a]NMBR = xxxyyy7139[0d]
>03/15 15:08:07 yS1    CND: NMBR = xxxyyy7139
>03/15 15:08:07 yS1    CND: found: xxxyyy7139
>03/15 15:08:07 yS1   wfr: rc=0, drn=0
>03/15 15:08:07 yS1    CND: check no: 'xxxyyy7139'
>03/15 15:08:07 yS1   CND: program "/home/don/ccid/cidmgetty.pl ttyS1 'xxxyyy7139' '' 0 '' >/dev/console 2>&1 </dev/null"
>03/15 15:08:08 yS1   CND: rc=0x100
>03/15 15:08:08 ##### denied caller dev=ttyS1, pid=2294, caller='xxxyyy7139'
>
>03/15 15:08:08 yS1   waiting for line to clear (VTIME=80), read: AME = RUSSELL DON    [0d][0a][0d][0a]RING[0d][0a]
>03/15 15:08:20 yS1   waiting for line to clear (VTIME=3), read: 
>03/15 15:08:21 yS1   removing lock file
>03/15 15:08:21 yS1  waiting...

Actions: View

Attachments on bug 232522: 150181 | 150250 | 155149 | 161315 | 301512 | 301513 | 301514 | 301515 | 301519