Link to home
Start Free TrialLog in
Avatar of daluu
daluuFlag for United States of America

asked on

Can parse one modem log file but not another - why?

We have an in-house Perl solution for making modems dial into our System Under Test (SUT). At the end of each test, if the modem successfully dialed in, the Perl script would parse the Windows modem log to extract the connection speed between the modem and our SUT.

We have the solution set up on a Windows 2000 PC, so the logs are in C:\WINNT\ModemLog_*.txt.

Recently, we wanted to add more modems to the test set, so I set up a new machine for this and this new machine runs Windows XP, so I made some tweaks to support XP. The path for XP is C:\Windows\ModemLog_*.txt.

What I've found is that the Perl solution can extract modem connect speed on modems in Windows 2000 but not on modems in Windows XP. From this issue, I extracted the parsing portion of the Perl script for debugging. I haven't looked into great detail the differences between the modem logs on each computer, but I assume they should be similar, at least I know the connect speed log entry hasn't changed from 2000 to XP.

When I did debugging with the "bad" modem logs under Windows 2000 and Perl, it still fails.

I'm puzzled. Anybody have any idea why the "bad" modem log is bad? Logs and Perl code snippet shown below.

---Begin - Perl code snippet---
sub GetConnectSpeed {
   my ($path, $i, $modemfile, $speed);
   $speed = "crap";
   $path = $_[0];
   print "DEBUG: modem log = ".$path."\n";
   # Open and read log file then extract connect speed.
   open (FILE, '<', "$path") or die "FATAL ERROR: Could not open Win32 system modem log to read connect speed.\n";
   @files = <FILE>;
   close (FILE);
   foreach $i (@files){
      chomp;
      #print "DEGUG: find speed\n";
      if ($i =~ /([0-9]+\s*bps)/g) {
      #if ($i =~ /Command Echo/i) {
         $speed = $1;
         print "DEBUG: conn speed - ".$speed."\n";
         last;
      }
   }
   close (FILE);
   if ($speed eq "crap") {
      print "DEBUG: speed !found? - ".$speed."\n";
      return ("Not Found");
   } else {
      return ($speed);
   }  
}
print "Connect speed = ".GetConnectSpeed(@ARGV[0]);
---End - Perl code snippet---


---Begin - Perl debugging runtime result---

D:\WUTemp>getModemConnSpeed.pl "D:\WUTemp\ModemLog_3Com Windows Modem ISA ADI.t
xt"
DEBUG: modem log = D:\WUTemp\ModemLog_3Com Windows Modem ISA ADI.txt
DEBUG: conn speed - 31200bps
Connect speed = 31200bps

D:\WUTemp>getModemConnSpeed.pl "D:\WUTemp\ModemLog_Zoom V92 PC Card.txt"
DEBUG: modem log = D:\WUTemp\ModemLog_Zoom V92 PC Card.txt
DEBUG: speed !found? - crap
Connect speed = Not Found

D:\WUTemp>
---End - Perl debugging runtime result---


---Begin - Good modem log, named ModemLog_3Com Windows Modem ISA ADI.txt---
10-02-2007 13:34:34.623 - File: C:\WINNT\system32\unimdm.tsp, Version 5.0.2195 - Retail
10-02-2007 13:34:34.623 - File: C:\WINNT\system32\unimdmat.dll, Version 5.0.2195 - Retail
10-02-2007 13:34:34.623 - File: C:\WINNT\system32\uniplat.dll, Version 5.0.2195 - Retail
10-02-2007 13:34:34.633 - File: C:\WINNT\system32\drivers\modem.sys, Version 5.0.2195 - Retail
10-02-2007 13:34:34.633 - File: C:\WINNT\system32\modemui.dll, Version 5.0.2195 - Retail
10-02-2007 13:34:34.633 - Modem type: 3Com Windows Modem ISA ADI
10-02-2007 13:34:34.633 - Modem inf path: mdm3cisa.inf
10-02-2007 13:34:34.633 - Modem inf section: ADI_Device
10-02-2007 13:34:34.633 - Opening Modem
10-02-2007 13:34:34.633 - 115200,8,N,1, ctsfl=1, rtsctl=2
10-02-2007 13:34:34.633 - Initializing modem.
10-02-2007 13:34:34.643 - Send: AT<cr>
10-02-2007 13:34:34.673 - TSP(0000): Making call
10-02-2007 13:34:34.694 - Recv: <cr><lf>OK<cr><lf>
10-02-2007 13:34:34.694 - Interpreted response: OK
10-02-2007 13:34:34.704 - Send: AT&F1E0Q0V1&C1&D2S0=0<cr>
10-02-2007 13:34:34.744 - Recv: <cr><lf>OK<cr><lf>
10-02-2007 13:34:34.744 - Interpreted response: OK
10-02-2007 13:34:34.754 - Send: AT&A0<cr>
10-02-2007 13:34:34.794 - Recv: <cr><lf>OK<cr><lf>
10-02-2007 13:34:34.794 - Interpreted response: OK
10-02-2007 13:34:34.804 - Send: AT&A0<cr>
10-02-2007 13:34:34.844 - Recv: <cr><lf>OK<cr><lf>
10-02-2007 13:34:34.844 - Interpreted response: OK
10-02-2007 13:34:34.854 - Send: ATS7=60S19=0L0M1&M4&K1&H1&R2&I0B0X4<cr>
10-02-2007 13:34:34.894 - Recv: <cr><lf>OK<cr><lf>
10-02-2007 13:34:34.894 - Interpreted response: OK
10-02-2007 13:34:34.894 - Waiting for a call.
10-02-2007 13:34:34.904 - Send: ATS0=0<cr>
10-02-2007 13:34:34.944 - Recv: <cr><lf>OK<cr><lf>
10-02-2007 13:34:34.944 - Interpreted response: OK
10-02-2007 13:34:34.944 - 115200,8,N,1, ctsfl=1, rtsctl=2
10-02-2007 13:34:34.944 - Initializing modem.
10-02-2007 13:34:34.954 - Send: AT<cr>
10-02-2007 13:34:34.994 - Recv: <cr><lf>OK<cr><lf>
10-02-2007 13:34:34.994 - Interpreted response: OK
10-02-2007 13:34:35.004 - Send: AT&F1E0Q0V1&C1&D2S0=0<cr>
10-02-2007 13:34:35.044 - Recv: <cr><lf>OK<cr><lf>
10-02-2007 13:34:35.044 - Interpreted response: OK
10-02-2007 13:34:35.054 - Send: AT&A0<cr>
10-02-2007 13:34:35.094 - Recv: <cr><lf>OK<cr><lf>
10-02-2007 13:34:35.094 - Interpreted response: OK
10-02-2007 13:34:35.104 - Send: AT&A0<cr>
10-02-2007 13:34:35.144 - Recv: <cr><lf>OK<cr><lf>
10-02-2007 13:34:35.144 - Interpreted response: OK
10-02-2007 13:34:35.154 - Send: ATS7=60S19=0L0M1&M4&K1&H1&R2&I0B0X4<cr>
10-02-2007 13:34:35.194 - Recv: <cr><lf>OK<cr><lf>
10-02-2007 13:34:35.194 - Interpreted response: OK
10-02-2007 13:34:35.194 - Dialing.
10-02-2007 13:34:35.194 - TSP(0000): LINEEVENT: LINECALLSTATE_DIALING
10-02-2007 13:34:35.194 - TSP(0000): LINEEVENT: LINECALLSTATE_PROCEEDING
10-02-2007 13:34:35.204 - Send: ATDT#######<cr>
10-02-2007 13:35:00.710 - Recv: <cr><lf>CONNECT 31200<cr><lf>
10-02-2007 13:35:00.710 - Interpreted response: Connect
10-02-2007 13:35:00.710 - Connection established at 31200bps.
10-02-2007 13:35:00.710 - Error-control off or unknown.
10-02-2007 13:35:00.710 - Data compression off or unknown.
10-02-2007 13:35:00.710 - TSP(0000): LINEEVENT: LINECALLSTATE_CONNECTED
10-02-2007 13:35:25.055 - TSP(0000): Dropping call
10-02-2007 13:35:25.055 - Hanging up the modem.
10-02-2007 13:35:25.055 - Hardware hangup by lowering DTR.
10-02-2007 13:35:26.297 - Detected CD dropped from lowering DTR
10-02-2007 13:35:26.297 - Recv: <cr><lf>NO CARRIER<cr><lf>
10-02-2007 13:35:26.297 - Interpreted response: No Carrier
10-02-2007 13:35:26.307 - Send: ATH<cr>
10-02-2007 13:35:26.347 - Recv: <cr><lf>OK<cr><lf>
10-02-2007 13:35:26.347 - Interpreted response: OK
10-02-2007 13:35:26.357 - 115200,8,N,1, ctsfl=1, rtsctl=2
10-02-2007 13:35:26.357 - Initializing modem.
10-02-2007 13:35:26.367 - Send: AT<cr>
10-02-2007 13:35:26.397 - Recv: <cr><lf>OK<cr><lf>
10-02-2007 13:35:26.397 - Interpreted response: OK
10-02-2007 13:35:26.407 - Send: AT&F1E0Q0V1&C1&D2S0=0<cr>
10-02-2007 13:35:26.447 - Recv: <cr><lf>OK<cr><lf>
10-02-2007 13:35:26.447 - Interpreted response: OK
10-02-2007 13:35:26.457 - Send: AT&A0<cr>
10-02-2007 13:35:26.497 - Recv: <cr><lf>OK<cr><lf>
10-02-2007 13:35:26.497 - Interpreted response: OK
10-02-2007 13:35:26.507 - Send: AT&A0<cr>
10-02-2007 13:35:26.547 - Recv: <cr><lf>OK<cr><lf>
10-02-2007 13:35:26.547 - Interpreted response: OK
10-02-2007 13:35:26.557 - Send: ATS7=60S19=0L0M1&M4&K1&H1&R2&I0B0X4<cr>
10-02-2007 13:35:26.597 - Recv: <cr><lf>OK<cr><lf>
10-02-2007 13:35:26.597 - Interpreted response: OK
10-02-2007 13:35:26.597 - Waiting for a call.
10-02-2007 13:35:26.607 - Send: ATS0=0<cr>
10-02-2007 13:35:26.647 - Recv: <cr><lf>OK<cr><lf>
10-02-2007 13:35:26.647 - Interpreted response: OK
10-02-2007 13:35:26.647 - TSP(0000): LINEEVENT: LINECALLSTATE_DISCONNECTED(0x1)
10-02-2007 13:35:26.647 - TSP(0000): LINEEVENT: LINECALLSTATE_IDLE
10-02-2007 13:35:26.647 - TSP(0000): Dropping call
10-02-2007 13:35:26.647 - TSP(0000): Closing Call

---End - Good modem log, named ModemLog_3Com Windows Modem ISA ADI.txt---


---Begin - Bad modem log, named ModemLog_Zoom V92 PC Card.txt---
09-07-2007 13:46:13.859 - File: C:\WINDOWS\system32\tapisrv.dll, Version 5.1.2600  
09-07-2007 13:46:13.859 - File: C:\WINDOWS\system32\unimdm.tsp, Version 5.1.2600  
09-07-2007 13:46:13.859 - File: C:\WINDOWS\system32\unimdmat.dll, Version 5.1.2600  
09-07-2007 13:46:13.859 - File: C:\WINDOWS\system32\uniplat.dll, Version 5.1.2600  
09-07-2007 13:46:13.859 - File: C:\WINDOWS\system32\drivers\modem.sys, Version 5.1.2600  
09-07-2007 13:46:13.875 - File: C:\WINDOWS\system32\modemui.dll, Version 5.1.2600  
09-07-2007 13:46:13.875 - File: C:\WINDOWS\system32\mdminst.dll, Version 5.1.2600  
09-07-2007 13:46:13.875 - Modem type: Zoom V92 PC Card
09-07-2007 13:46:13.875 - Modem inf path: acf_vap.inf
09-07-2007 13:46:13.875 - Modem inf section: Modem
09-07-2007 13:46:13.875 - Matching hardware ID: pcmcia\zoom-v92_pc_card-2e1e
09-07-2007 13:46:16.703 - Opening Modem
09-07-2007 13:46:16.703 - 115200,8,N,1, ctsfl=1, rtsctl=2
09-07-2007 13:46:16.703 - Initializing modem.
09-07-2007 13:46:16.703 - CTS is low while initializing modem.
09-07-2007 13:46:16.718 - Send: ATZ<cr>
09-07-2007 13:46:16.781 - TSP(0000): Making Call
09-07-2007 13:46:17.250 - Recv: ATZ<cr>
09-07-2007 13:46:17.250 - Command Echo
09-07-2007 13:46:17.421 - Recv: <cr><lf>OK<cr><lf>
09-07-2007 13:46:17.421 - Interpreted response: OK
09-07-2007 13:46:17.437 - Send: AT&F+IBC=0,0,0,,,,,0;+PCW=2;+PMH=1<cr>
09-07-2007 13:46:17.437 - Recv: AT&F+IBC=0,0,0,,,,,0;+PCW=2;+PMH=1<cr>
09-07-2007 13:46:17.437 - Command Echo
09-07-2007 13:46:17.484 - Recv: <cr><lf>OK<cr><lf>
09-07-2007 13:46:17.484 - Interpreted response: OK
09-07-2007 13:46:17.500 - Send: ATE0V1S0=0&C1&D2+MR=2;+DR=1;+ER=1;W2<cr>
09-07-2007 13:46:17.500 - Recv: ATE0V1S0=0&C1&D2+MR=2;+DR=1;+ER=1;W2<cr>
09-07-2007 13:46:17.500 - Command Echo
09-07-2007 13:46:17.531 - Recv: <cr><lf>OK<cr><lf>
09-07-2007 13:46:17.531 - Interpreted response: OK
09-07-2007 13:46:17.546 - Send: ATS7=60S30=0L1M1+ES=3,0,2;+DS=3;+IFC=2,2;BX4<cr>
09-07-2007 13:46:17.593 - Recv: <cr><lf>OK<cr><lf>
09-07-2007 13:46:17.593 - Interpreted response: OK
09-07-2007 13:46:17.593 - Waiting for a call.
09-07-2007 13:46:17.609 - Send: at+vcid=1<cr>
09-07-2007 13:46:17.640 - Recv: <cr><lf>OK<cr><lf>
09-07-2007 13:46:17.640 - Interpreted response: OK
09-07-2007 13:46:17.656 - Send: ATS0=0<cr>
09-07-2007 13:46:17.687 - Recv: <cr><lf>OK<cr><lf>
09-07-2007 13:46:17.687 - Interpreted response: OK
09-07-2007 13:46:17.687 - 115200,8,N,1, ctsfl=1, rtsctl=2
09-07-2007 13:46:17.687 - Initializing modem.
09-07-2007 13:46:17.703 - Send: ATZ<cr>
09-07-2007 13:46:17.875 - Recv: <cr><lf>OK<cr><lf>
09-07-2007 13:46:17.875 - Interpreted response: OK
09-07-2007 13:46:17.890 - Send: AT&F+IBC=0,0,0,,,,,0;+PCW=2;+PMH=1<cr>
09-07-2007 13:46:17.890 - Recv: AT&F+IBC=0,0,0,,,,,0;+PCW=2;+PMH=1<cr>
09-07-2007 13:46:17.890 - Command Echo
09-07-2007 13:46:17.937 - Recv: <cr><lf>OK<cr><lf>
09-07-2007 13:46:17.937 - Interpreted response: OK
09-07-2007 13:46:17.953 - Send: ATE0V1S0=0&C1&D2+MR=2;+DR=1;+ER=1;W2<cr>
09-07-2007 13:46:17.953 - Recv: ATE0V1S0=0&C1&D2+MR=2;+DR=1;+ER=1;W2<cr>
09-07-2007 13:46:17.953 - Command Echo
09-07-2007 13:46:17.984 - Recv: <cr><lf>OK<cr><lf>
09-07-2007 13:46:17.984 - Interpreted response: OK
09-07-2007 13:46:18.000 - Send: ATS7=60S30=0L1M1+ES=3,0,2;+DS=3;+IFC=2,2;BX4<cr>
09-07-2007 13:46:18.046 - Recv: <cr><lf>OK<cr><lf>
09-07-2007 13:46:18.046 - Interpreted response: OK
09-07-2007 13:46:18.046 - Dialing.
09-07-2007 13:46:18.046 - TSP Completing Async Operation(0x00010078) Status 0x00000000
09-07-2007 13:46:18.046 - TSP(0000): LINEEVENT: LINECALLSTATE_DIALING
09-07-2007 13:46:18.046 - TSP(0000): LINEEVENT: LINECALLSTATE_PROCEEDING
09-07-2007 13:46:18.062 - Send: ATDT#######<cr>
09-07-2007 13:46:41.734 - Recv: <cr><lf>+MCR: V34<cr><lf>
09-07-2007 13:46:41.734 - Interpreted response: Informative
09-07-2007 13:46:41.734 - Recv: <cr><lf>+MRR: 33600<cr><lf>
09-07-2007 13:46:41.734 - Interpreted response: Informative
09-07-2007 13:46:42.656 - Recv: <cr><lf>+ER: LAPM<cr><lf>
09-07-2007 13:46:42.656 - Interpreted response: Informative
09-07-2007 13:46:42.656 - Recv: <cr><lf>+DR: V44<cr><lf>
09-07-2007 13:46:42.656 - Interpreted response: Informative
09-07-2007 13:46:42.656 - Recv: <cr><lf>CONNECT 33600<cr><lf>
09-07-2007 13:46:42.656 - Interpreted response: Connect
09-07-2007 13:46:42.656 - Connection established at 33600bps.
09-07-2007 13:46:42.656 - Error-control on.
09-07-2007 13:46:42.656 - Data compression on.
09-07-2007 13:46:42.656 - TSP(0000): LINEEVENT: LINECALLSTATE_CONNECTED
09-07-2007 13:47:12.656 - Read: Total: 809, Per/Sec: 21, Written: Total: 1048, Per/Sec: 30
09-07-2007 13:47:17.515 - TSP(0000): Dropping Call
09-07-2007 13:47:17.515 - Hanging up the modem.
09-07-2007 13:47:17.515 - Hardware hangup by lowering DTR.
09-07-2007 13:47:17.843 - Detected CD dropped from lowering DTR
09-07-2007 13:47:18.640 - Recv: <cr><lf>NO CARRIER<cr><lf>
09-07-2007 13:47:18.640 - Interpreted response: No Carrier
09-07-2007 13:47:18.656 - Send: ATH<cr>
09-07-2007 13:47:18.687 - Recv: <cr><lf>OK<cr><lf>
09-07-2007 13:47:18.687 - Interpreted response: OK
09-07-2007 13:47:18.687 - 115200,8,N,1, ctsfl=1, rtsctl=2
09-07-2007 13:47:18.687 - Initializing modem.
09-07-2007 13:47:18.703 - Send: ATZ<cr>
09-07-2007 13:47:18.875 - Recv: <cr><lf>OK<cr><lf>
09-07-2007 13:47:18.875 - Interpreted response: OK
09-07-2007 13:47:18.890 - Send: AT&F+IBC=0,0,0,,,,,0;+PCW=2;+PMH=1<cr>
09-07-2007 13:47:18.890 - Recv: AT&F+IBC=0,0,0,,,,,0;+PCW=2;+PMH=1<cr>
09-07-2007 13:47:18.890 - Command Echo
09-07-2007 13:47:18.937 - Recv: <cr><lf>OK<cr><lf>
09-07-2007 13:47:18.937 - Interpreted response: OK
09-07-2007 13:47:18.953 - Send: ATE0V1S0=0&C1&D2+MR=2;+DR=1;+ER=1;W2<cr>
09-07-2007 13:47:18.953 - Recv: ATE0V1S0=0&C1&D2+MR=2;+DR=1;+ER=1;W2<cr>
09-07-2007 13:47:18.953 - Command Echo
09-07-2007 13:47:18.984 - Recv: <cr><lf>OK<cr><lf>
09-07-2007 13:47:18.984 - Interpreted response: OK
09-07-2007 13:47:19.000 - Send: ATS7=60S30=0L1M1+ES=3,0,2;+DS=3;+IFC=2,2;BX4<cr>
09-07-2007 13:47:19.031 - Recv: <cr><lf>OK<cr><lf>
09-07-2007 13:47:19.031 - Interpreted response: OK
09-07-2007 13:47:19.046 - Waiting for a call.
09-07-2007 13:47:19.062 - Send: at+vcid=1<cr>
09-07-2007 13:47:19.093 - Recv: <cr><lf>OK<cr><lf>
09-07-2007 13:47:19.093 - Interpreted response: OK
09-07-2007 13:47:19.109 - Send: ATS0=0<cr>
09-07-2007 13:47:19.140 - Recv: <cr><lf>OK<cr><lf>
09-07-2007 13:47:19.140 - Interpreted response: OK
09-07-2007 13:47:19.140 - TSP(0000): LINEEVENT: LINECALLSTATE_DISCONNECTED(0x1)
09-07-2007 13:47:19.140 - TSP(0000): LINEEVENT: LINECALLSTATE_IDLE
09-07-2007 13:47:19.140 - TSP Completing Async Operation(0x00010045) Status 0x00000000
09-07-2007 13:47:19.140 - TSP(0000): Dropping Call
09-07-2007 13:47:19.140 - TSP Completing Async Operation(0x00010034) Status 0x00000000
09-07-2007 13:47:19.140 - TSP(0000): Closing Call
09-07-2007 13:47:19.140 - Session Statistics:
09-07-2007 13:47:19.140 -                Reads : 108 bytes
09-07-2007 13:47:19.140 -                Writes: 138 bytes

---End - Bad modem log, named ModemLog_Zoom V92 PC Card.txt---
Avatar of Adam314
Adam314

You should add use strict and use warnings to your script.
You should add the reason for not being able to open a file.
There is no need to read the entire file into memory at one time.
The chomp statement you have does nothing.

Try this version
sub GetConnectSpeed {
      open(IN,"<", $_[0]) or die "FATAL ERROR: Could not open Win32 system modem log to read connect speed: $!.\n";
      while(<IN>) {
            next unless /(\d+\s*bps)/;
            close(IN);
            return $1;
      }
      close(IN);
      return "Not Found";
}
Avatar of daluu

ASKER

thanks, I'll try your version. hopefully that will work.

I didn't write the code, I had inherited it from the person before me and never bothered to refine it as they say "don't fix it if it isn't broken" or something like that.
Avatar of daluu

ASKER

Your suggested changes still gives the same results. I'm guessing, it has to do with the bad modem log file. Maybe a bad character or formatting in the text file that causes Perl to skip over the connect speed?
Avatar of daluu

ASKER

I found some very interesting things. It appears to be something that Windows does secretly behind the scenes. If only I could figure out what the heck's going on.

* rename good log file to bad log file and speed is found
* rename bad log file to good log file and speed is not found
* replace contents of bad log with good log and speed is not found
* replace contents of good log with bad log and speed is found

* test with short excerpt of logs containing only the connect speed entries - if started test using good log, then replace with contents of bad log, then will work. Reverse process and it will fail.

Since the logs are simply text files, and a brief review of the contents & format indicates they are roughly similar, there must be some wacky thing that is different about the files. The only things that come to mind for me are that the file names are different and that one came from an XP machine.
Avatar of daluu

ASKER

One more thing, if I copy the log contents that I've posted here and save to 2 text files with the same names, then test, both speeds can be found. This is so weird.
ASKER CERTIFIED SOLUTION
Avatar of mjcoyne
mjcoyne

Link to home
membership
This solution is only available to members.
To access this solution, you must be a member of Experts Exchange.
Start Free Trial
If you really want to scrub the file for any weird characters (NULLs, control characters, etc.), try something like:

#!/usr/bin/perl -w
use strict;
my %allowed;

open (LOG, "original_log.txt") or die "Can't open original_log.txt: $!\n";
open (NEW, ">new_log.txt") or die "Can't open new_log.txt: $!\n";

for (9, 10, 12, 13, 32..126) {
    $allowed{$_}++;
}

while (<LOG>) {
    my @line = split //;
    for (@line) {
        print NEW if (exists $allowed{ord($_)});
    }
}
Avatar of daluu

ASKER

Thanks, that worked.

Interesting how the XP system logs with extra data/characters. I don't think it's modem specific as I have several modms on the XP system that have the same problem. Or maybe newer modems add the extra stuff as the Windows 2000 system has older modems as well.
I wonder if it's a hardware issue (serial port or modem configuration differences, maybe? e.g. 7-bit or 8-bit character sets?) rather than OS differences...

Or perhaps the default serial port configuration is different between the OSes?

BTW, which fixed it -- using the regular expression from the other direction, or stripping NULLs?
Avatar of daluu

ASKER

stripping the NULLs