Multiple lines of output are causing timeouts

Question

Multiple lines of output are causing timeouts

treydock opened this issue 4 years ago · 3 comments

I am attempting to write expect around some queries of Tivoli Storage Manager (IBM Spectrum Protect) and have found that if my queries return only a few lines of output everything works but if my queries return many lines of output I hit the expect timeout.

I modified my program to do a simpler SSH command where executing hostname is successful but an operation that lists the contents of a directory with a few lines of output times out.

package main

import (
	"log"
	"os"
	"regexp"
	"time"

	expect "github.com/google/goexpect"
)

var (
	passRE   = regexp.MustCompile("password:")
	promptRE = regexp.MustCompile(`\[tdockendorf@repo ~\]`)
)

func main() {
	cmd := "ssh repo"
	timeout := time.Duration(5) * time.Second
	e, _, err := expect.Spawn(cmd, timeout, expect.Verbose(true), expect.VerboseWriter(os.Stdout))
	if err != nil {
		log.Fatal(err)
	}
	defer e.Close()

	content, matches, err := e.Expect(passRE, timeout)
	if err != nil {
		log.Fatalf("error getting password prompt: %v", err)
	}
	log.Printf("content1: %s matches1: %v", content, matches)
	err = e.Send(os.Getenv("PASSWORD") + "\n")
	if err != nil {
		log.Fatalf("error sending password: %v", err)
	}
	content, matches, err = e.Expect(promptRE, timeout)
	if err != nil {
		log.Fatalf("error getting prompt: %v", err)
	}
	log.Printf("content2: %s matches2: %v", content, matches)
	err = e.Send("hostname\n")
	if err != nil {
		log.Fatalf("error sending command1: %v", err)
	}
	content, matches, err = e.Expect(promptRE, timeout)
	if err != nil {
		log.Fatalf("error getting prompt: %v", err)
	}
	log.Printf("content3: %s matches3: %v", content, matches)
	err = e.Send("ls -la /var/www/repos/public/ondemand/\n")
	if err != nil {
		log.Fatalf("error sending command2: %v", err)
	}
	content, matches, err = e.Expect(regexp.MustCompile("Protect:"), timeout)
	if err != nil {
		log.Fatalf("error getting prompt2: %v", err)
	}
	log.Printf("content4: %s matches4: %v", content, matches)
	e.Send("exit\n")
}

OUTPUT:

$ ./test
Match for RE: "password:" found: ["password:"] Buffer: tdockendorf@repo's password: 
2020/11/11 10:26:14 content1: tdockendorf@repo's password:  matches1: [password:]
Sent: "OMIT-PASSWORD\n"
Match for RE: "\\[tdockendorf@repo ~\\]" found: ["[tdockendorf@repo ~]"] Buffer: 
Last login: Wed Nov 11 10:24:09 2020 from pitzer-rw01.ten.osc.edu
******************************************************************************

   This system is for the use of authorized users only.  Individuals using
   this computer system without authority, or in excess of their authority,
   are subject to having all of their activities on this system monitored
   and recorded by system personnel.  In the course of monitoring individuals
   improperly using this system, or in the course of system maintenance,
   the activities of authorized users may also be monitored.  Anyone using
   this system expressly consents to such monitoring and is advised that if
   such monitoring reveals possible evidence of criminal activity, system
   personnel may provide the evidence of such monitoring to law enforcement
   officials.

******************************************************************************
[tdockendorf@repo ~]$ 
2020/11/11 10:26:14 content2: 
Last login: Wed Nov 11 10:24:09 2020 from pitzer-rw01.ten.osc.edu
******************************************************************************

   This system is for the use of authorized users only.  Individuals using
   this computer system without authority, or in excess of their authority,
   are subject to having all of their activities on this system monitored
   and recorded by system personnel.  In the course of monitoring individuals
   improperly using this system, or in the course of system maintenance,
   the activities of authorized users may also be monitored.  Anyone using
   this system expressly consents to such monitoring and is advised that if
   such monitoring reveals possible evidence of criminal activity, system
   personnel may provide the evidence of such monitoring to law enforcement
   officials.

******************************************************************************
[tdockendorf@repo ~]$  matches2: [[tdockendorf@repo ~]]
Sent: "hostname\n"
Match for RE: "\\[tdockendorf@repo ~\\]" found: ["[tdockendorf@repo ~]"] Buffer: repo.OMIT
[tdockendorf@repo ~]$ 
2020/11/11 10:26:14 content3: repo.OMIT
[tdockendorf@repo ~]$  matches3: [[tdockendorf@repo ~]]
Sent: "ls -la /var/www/repos/public/ondemand/\n"
2020/11/11 10:26:19 error getting prompt2: expect: timer expired after 5 seconds

Commands executed outside the program:

$ ssh repo
tdockendorf@repo's password: 
Last login: Wed Nov 11 10:26:14 2020 from pitzer-rw01.ten.osc.edu
******************************************************************************

   This system is for the use of authorized users only.  Individuals using
   this computer system without authority, or in excess of their authority,
   are subject to having all of their activities on this system monitored
   and recorded by system personnel.  In the course of monitoring individuals
   improperly using this system, or in the course of system maintenance,
   the activities of authorized users may also be monitored.  Anyone using
   this system expressly consents to such monitoring and is advised that if
   such monitoring reveals possible evidence of criminal activity, system
   personnel may provide the evidence of such monitoring to law enforcement
   officials.

******************************************************************************
[tdockendorf@repo ~]$ hostname
repo.hpc.osc.edu
[tdockendorf@repo ~]$ time ls -la /var/www/repos/public/ondemand/
total 80
drwxrwxr-x 13 tdockendorf oodpkg  4096 Aug 19 09:04 .
drwxrwxr-x 23 tdockendorf    103  8192 Apr  5  2019 ..
drwxr-xr-x  4 oodpkg      oodpkg  4096 May  2  2018 1.3
drwxr-xr-x  4 oodpkg      oodpkg  4096 Jan  7  2019 1.4
drwxr-xr-x  4 oodpkg      oodpkg  4096 Feb  4  2019 1.5
drwxr-xr-x  4 oodpkg      oodpkg  4096 Sep 30  2019 1.6
drwxr-xr-x  4 oodpkg      oodpkg  4096 Aug 19 13:32 1.7
drwxr-xr-x  4 oodpkg      oodpkg  4096 Aug 19 09:04 1.8
drwxrwxr-x  2 oodpkg      oodpkg 16384 Apr  8  2020 archive
drwxrwxr-x  6 oodpkg      oodpkg  4096 Nov  6 11:28 build
drwxr-xr-x  4 oodpkg      oodpkg  4096 Jul  3  2019 ci
drwxr-xr-x  2 oodpkg      oodpkg  4096 Nov  5 14:11 images
drwxr-xr-x  4 oodpkg      oodpkg 12288 Aug 19 13:34 latest
-rw-r--r--  1 root        root    1739 Feb 13  2018 RPM-GPG-KEY-ondemand

real    0m0.008s
user    0m0.000s
sys     0m0.004s

Answer 1 · 2020-11-11T16:03:01.000Z

So the issue with above application was a typo in copying the TSM script to do SSH, so the above is resolved sort of but now the output length limit is seeming to be cause problems for TSM queries. The query I am executing will return 31 lines and when I execute the query outside expect the time of the query is 0.544 seconds. If I limit the output to 20 results I don't see a timeout but then the next duplicate query without LIMIT will time out:

Code:

package main

import (
	"flag"
	"fmt"
	"log"
	"os"
	"regexp"
	"time"

	expect "github.com/google/goexpect"
)

var (
	servername = flag.String("servername", "", "TSM servername")
	password   = flag.String("password", "", "password for dsmadmc")
	passRE     = regexp.MustCompile("password:")
	promptRE   = regexp.MustCompile("(?m)Protect: [a-zA-Z0-9]+>")
)

func main() {
	flag.Parse()
	os.Setenv("DSM_LOG", "/tmp/test")
	cmd := fmt.Sprintf("/usr/bin/dsmadmc -servername=%s -DATAONLY=YES -COMMAdelimited -id=somwell", *servername)
	timeout := time.Duration(15) * time.Second
	e, _, err := expect.Spawn(cmd, timeout, expect.NoCheck(), expect.Verbose(true), expect.VerboseWriter(os.Stdout))
	if err != nil {
		log.Fatal(err)
	}
	defer e.Close()

	content, matches, err := e.Expect(passRE, timeout)
	if err != nil {
		log.Fatalf("error getting password prompt: %v", err)
	}
	log.Printf("content1: %s matches1: %v", content, matches)
	err = e.Send(*password + "\n")
	if err != nil {
		log.Fatalf("error sending password: %v", err)
	}
	content, matches, err = e.Expect(promptRE, timeout)
	if err != nil {
		log.Fatalf("error getting pre prompt: %v", err)
	}
	log.Printf("content2: %s matches2: %v", content, matches)
	err = e.Send("SELECT DEVCLASS,PCT_UTILIZED,POOLTYPE,STGPOOL_NAME,STG_TYPE FROM stgpools LIMIT 20\n")
	if err != nil {
		log.Fatalf("error sending command1: %v", err)
	}
	content, matches, err = e.Expect(regexp.MustCompile("(?m)Protect:"), timeout)
	if err != nil {
		log.Fatalf("error getting post prompt1: %v", err)
	}
	log.Printf("content3: %s matches3: %v", content, matches)
	err = e.Send("SELECT DEVCLASS,PCT_UTILIZED,POOLTYPE,STGPOOL_NAME,STG_TYPE FROM stgpools\n")
	if err != nil {
		log.Fatalf("error sending command2: %v", err)
	}
	content, matches, err = e.Expect(regexp.MustCompile("(?m)Protect:"), timeout)
	if err != nil {
		log.Fatalf("error getting post prompt2: %v", err)
	}
	log.Printf("content4: %s matches4: %v", content, matches)
	e.Send("exit\n")
}

OUTPUT:

Match for RE: "password:" found: ["password:"] Buffer: Enter your password:  
2020/11/11 10:59:43 content1: Enter your password:   matches1: [password:]
Sent: "OMIT-PASSWORD\n"
Match for RE: "(?m)Protect: [a-zA-Z0-9]+>" found: ["Protect: SP02>"] Buffer: 


Protect: SP02>
2020/11/11 10:59:43 content2: 


Protect: SP02> matches2: [Protect: SP02>]
Sent: "SELECT DEVCLASS,PCT_UTILIZED,POOLTYPE,STGPOOL_NAME,STG_TYPE FROM stgpools LIMIT 20\n"
Match for RE: "(?m)Protect:" found: ["Protect:"] Buffer: SELECT DEVCLASS,PCT_UTILIZED,POOLTYPE,STGPOOL_NAME,STG_TYPE FROM stgpools LIMIT 20
DISK,0.0,PRIMARY,ARCHIVEPOOL,DEVCLASS
DISK,0.0,PRIMARY,BACKUPPOOL,DEVCLASS
DCFILEE,27.4,PRIMARY,EPFDHG,DEVCLASS
DCFILEE,26.9,PRIMARY,EPFESS,DEVCLASS
DCFILEE,0.0,PRIMARY,EPFEXPPROJ,DEVCLASS
DCFILEE,0.0,PRIMARY,EPFGPFS,DEVCLASS
DCFILEE,0.0,PRIMARY,EPFHOME,DEVCLASS
DCFILEE,0.0,PRIMARY,EPFHSM,DEVCLASS
DCFILEE,0.0,PRIMARY,EPFNETAPP,DEVCLASS
DCFILEE,0.0,PRIMARY,EPFNETSYS,DEVCLASS
DCFILEE,0.0,PRIMARY,EPFXTRN,DEVCLASS
DCULT7E,0.6,PRIMARY,EPTDHG,DEVCLASS
DCULT6E,0.5,PRIMARY,EPTDHG6,DEVCLASS
DCULT7E,1.3,PRIMARY,EPTESS,DEVCLASS
DCULT6E,20.9,PRIMARY,EPTESS6,DEVCLASS
DCULT6E,0.0,PRIMARY,EPTUSRPROJ,DEVCLASS
DCFILE,0.0,PRIMARY,PFEXPPROJ,DEVCLASS
DCFILE,34.3,PRIMARY,PFGPFS,DEVCLASS
DCFILE,0.0,PRIMARY,PFHSM,DEVCLASS
DCFILE,47.3,PRIMARY,PFNETAPP,DEVCLASS

Protect: SP02>
2020/11/11 10:59:43 content3: SELECT DEVCLASS,PCT_UTILIZED,POOLTYPE,STGPOOL_NAME,STG_TYPE FROM stgpools LIMIT 20
DISK,0.0,PRIMARY,ARCHIVEPOOL,DEVCLASS
DISK,0.0,PRIMARY,BACKUPPOOL,DEVCLASS
DCFILEE,27.4,PRIMARY,EPFDHG,DEVCLASS
DCFILEE,26.9,PRIMARY,EPFESS,DEVCLASS
DCFILEE,0.0,PRIMARY,EPFEXPPROJ,DEVCLASS
DCFILEE,0.0,PRIMARY,EPFGPFS,DEVCLASS
DCFILEE,0.0,PRIMARY,EPFHOME,DEVCLASS
DCFILEE,0.0,PRIMARY,EPFHSM,DEVCLASS
DCFILEE,0.0,PRIMARY,EPFNETAPP,DEVCLASS
DCFILEE,0.0,PRIMARY,EPFNETSYS,DEVCLASS
DCFILEE,0.0,PRIMARY,EPFXTRN,DEVCLASS
DCULT7E,0.6,PRIMARY,EPTDHG,DEVCLASS
DCULT6E,0.5,PRIMARY,EPTDHG6,DEVCLASS
DCULT7E,1.3,PRIMARY,EPTESS,DEVCLASS
DCULT6E,20.9,PRIMARY,EPTESS6,DEVCLASS
DCULT6E,0.0,PRIMARY,EPTUSRPROJ,DEVCLASS
DCFILE,0.0,PRIMARY,PFEXPPROJ,DEVCLASS
DCFILE,34.3,PRIMARY,PFGPFS,DEVCLASS
DCFILE,0.0,PRIMARY,PFHSM,DEVCLASS
DCFILE,47.3,PRIMARY,PFNETAPP,DEVCLASS

Protect: SP02> matches3: [Protect:]
Sent: "SELECT DEVCLASS,PCT_UTILIZED,POOLTYPE,STGPOOL_NAME,STG_TYPE FROM stgpools\n"
2020/11/11 10:59:58 error getting post prompt2: expect: timer expired after 15 seconds

Using outside expect:

bash-4.2$ /usr/bin/dsmadmc -servername=sp02.OMIT -DATAONLY=YES -COMMAdelimited -id=somwell
Enter your password:  


Protect: SP02>SELECT DEVCLASS,PCT_UTILIZED,POOLTYPE,STGPOOL_NAME,STG_TYPE FROM stgpools
DISK,0.0,PRIMARY,ARCHIVEPOOL,DEVCLASS
DISK,0.0,PRIMARY,BACKUPPOOL,DEVCLASS
DCFILEE,27.4,PRIMARY,EPFDHG,DEVCLASS
DCFILEE,26.9,PRIMARY,EPFESS,DEVCLASS
DCFILEE,0.0,PRIMARY,EPFEXPPROJ,DEVCLASS
DCFILEE,0.0,PRIMARY,EPFGPFS,DEVCLASS
DCFILEE,0.0,PRIMARY,EPFHOME,DEVCLASS
DCFILEE,0.0,PRIMARY,EPFHSM,DEVCLASS
DCFILEE,0.0,PRIMARY,EPFNETAPP,DEVCLASS
DCFILEE,0.0,PRIMARY,EPFNETSYS,DEVCLASS
DCFILEE,0.0,PRIMARY,EPFXTRN,DEVCLASS
DCULT7E,0.6,PRIMARY,EPTDHG,DEVCLASS
DCULT6E,0.5,PRIMARY,EPTDHG6,DEVCLASS
DCULT7E,1.3,PRIMARY,EPTESS,DEVCLASS
DCULT6E,20.9,PRIMARY,EPTESS6,DEVCLASS
DCULT6E,0.0,PRIMARY,EPTUSRPROJ,DEVCLASS
DCFILE,0.0,PRIMARY,PFEXPPROJ,DEVCLASS
DCFILE,34.3,PRIMARY,PFGPFS,DEVCLASS
DCFILE,0.0,PRIMARY,PFHSM,DEVCLASS
DCFILE,47.3,PRIMARY,PFNETAPP,DEVCLASS
DCFILE,0.0,PRIMARY,PFNETSYS,DEVCLASS
DCULT7,0.0,PRIMARY,PTEXPPROJ,DEVCLASS
DCULT6,0.0,COPY,PTEXPPROJCP,DEVCLASS
DCULT7,35.3,PRIMARY,PTGPFS,DEVCLASS
DCULT7,0.0,COPY,PTGPFSCP,DEVCLASS
DCULT7,0.0,PRIMARY,PTHSM,DEVCLASS
DCULT7,7.2,PRIMARY,PTNETAPP,DEVCLASS
DCULT7,0.0,COPY,PTNETAPPCP,DEVCLASS
DCULT7,0.0,PRIMARY,PTNETSYS,DEVCLASS
DCULT7,0.0,COPY,PTNETSYSCP,DEVCLASS
DISK,0.0,PRIMARY,SPACEMGPOOL,DEVCLASS

Protect: SP02>quit
bash-4.2$

Answer 2 · 2020-11-11T16:08:43.000Z

An expect SSH program that dumps the text works:

https://gist.github.com/treydock/240167c26bfa858fc8c656f89197f056

So maybe this is an issue with the TSM command.

Answer 3 · 2020-11-11T17:36:35.000Z

I am chalking this issue up to issues with TSM, and for now just having that program write output to a file and reading the file and just sending commands with expect, and that works.