After upgrade launcher not working

usaajrm · Post by **usaajrm** » Mon Mar 14, 2011 10:09 pm

We upgraded the client. things continued to work. We upgraded the host to 1.8. Now its not working. I turned on debug using an example for the user's guide. This is the output. Any help would be appreciated.

[02:46:10.802774] CoZLauncher[N]: <0> version: 1.8.0 2011-02-03
[02:46:10.810754] CoZLauncher[N]: <1> Copyright (C) Dovetailed Technologies, LLC. 2006. All rights reserved.
[02:46:10.810777] CoZLauncher[D]: <1> target_user="myuserid", target_host="server3l", target_port="NULL"
[02:46:10.810814] CoZLauncher[D]: <1> sysname=B012
[02:46:10.810825] CoZLauncher[D]: <1> CoZLauncher process id=83952061. Parent pid=1
[02:46:10.810837] CoZLauncher[D]: <1> region size requested = 32768K, Actual below/above limit = 8168K / 1132544K
[21:46:10.824154] CoZLauncher: <5> Agent output WTO is ON
[21:46:10.824178] CoZLauncher: <5> ssh tunnelling is ON
[21:46:10.824187] CoZLauncher[D]: <5> coz_log=trace
[21:46:10.824198] CoZLauncher[D]: <5> server-path=/usr/local/coz/bin/cozserver
[21:46:10.824207] CoZLauncher[D]: <5> server-ports=8040-8048
[21:46:10.824215] CoZLauncher[D]: <5> ssh-shareas=YES
[21:46:10.824223] CoZLauncher[D]: <5> agent-path=/opt/dovetail/coz/bin/cozagent
[21:46:10.824234] CoZLauncher[D]: <5> agent-output-wto=true
[21:46:10.824243] CoZLauncher[D]: <5> server-env-COZ_TRSUB_US-ASCII=ISO8859-1
[21:46:10.824253] CoZLauncher[D]: <5> ssh-options=-vv
[21:46:10.824262] CoZLauncher[D]: <5> server-env-PASSWD_DSN=//OS.SHARE.COZ.SUPPORT.LIB(NWME)
[21:46:10.824271] CoZLauncher[D]: <5> server-env-SSH_ASKPASS=/usr/local/coz/bin/read_passwd_dsn.sh
[21:46:10.824282] CoZLauncher[D]: <5> server-env-DISPLAY=none
[21:46:10.824666] CoZLauncher[D]: <5> Set server environment variable:'COZ_TRSUB_US-ASCII'='ISO8859-1'
[21:46:10.824680] CoZLauncher[D]: <5> Set server environment variable:'PASSWD_DSN'='//OS.SHARE.COZ.SUPPORT.LIB(NWME)'
[21:46:10.824695] CoZLauncher[D]: <5> Set server environment variable:'SSH_ASKPASS'='/usr/local/coz/bin/read_passwd_dsn.
sh' [21:46:10.824711] CoZLauncher[D]: <5> Set server environment variable:'DISPLAY'='none'
[21:46:10.827095] CoZLauncher[D]: <6> Server port range: 8040-8048
[21:46:10.827122] CoZLauncher[D]: <6> Attempting to start socket listener on port 8040
[21:46:10.947988] CoZLauncher: <28> CoZServer listener socket bound to: 127.0.0.1:8040
[21:46:10.948438] CoZLauncher[D]: <28> server_cmd...

/usr/local/coz/bin/cozserver -sockfd 3

[21:46:10.950835] CoZLauncher[D]: <29> Started CoZServer process: 33620424
[21:46:10.957616] CoZLauncher[D]: <30> arg[3] = '-vv'

[21:46:10.957649] CoZLauncher[D]: <31> agent_cmd...

/bin/ssh -l id12345 -vv -R 8040:127.0.0.1:8040 server3l /opt/dovetail/coz/bin/cozagent
[21:46:10.960559] CoZLauncher[D]: <4294965> serverStderrThread completed
[21:46:10.961518] CoZLauncher[D]: <31> Started CoZAgent process: 33620411
[21:46:10.961701] CoZLauncher[D]: <32> About to start target command: ''
[21:46:10.962055] CoZLauncher[D]: <32> CoZServer (33620424) ended with RC=0
[21:46:10.962102] CoZLauncher[D]: <32> Signalling agent process
[21:46:10.962115] CoZLauncher[D]: <32> Sleep before Killing child process CozAgent (33620411)
[21:46:11.166361] CoZLauncher[D]: <4294965> First agent message received:
OpenSSH_5.0p1, OpenSSL 0.9.8k 25 Mar 2009
debug1: Reading configuration data /etc/ssh/ssh_config

debug1: zsshSmfSetConnSmfStatus: SMF status is 0

debug1: Rhosts Authentication disabled, originating port will not be trusted.

debug2: ssh_connect: needpriv 0

debug1: Connecting to server3l [10.160.2.236] port 22.

debug1: Connection established.

debug1: identity file /u/id12345/.ssh/id_rsa type -1

debug1: identity file /u/id12345/.ssh/id_dsa type -1

debug1: Remote protocol version 2.0, remote software version OpenSSH_4.3

debug1: match: OpenSSH_4.3 pat OpenSSH*

debug1: Enabling compatibility mode for protocol 2.0

debug1: Local version string SSH-2.0-OpenSSH_5.0

debug2: fd 3 setting O_NONBLOCK

debug1: SSH2_MSG_KEXINIT sent

debug1: SSH2_MSG_KEXINIT received

debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group1
4-sha1,diffie-hellman-group1-sha1

debug2: kex_parse_kexinit: ssh-rsa,ssh-dss

debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast1
28-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se

debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast1
28-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se

debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96
,hmac-md5-96

debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96
,hmac-md5-96

debug2: kex_parse_kexinit: none,zlib@openssh.com,zlib

debug2: kex_parse_kexinit: none,zlib@openssh.com,zlib

debug2: kex_parse_kexinit:

debug2: kex_parse_kexinit:

debug2: kex_parse_kexinit: first_kex_follows 0

debug2: kex_parse_kexinit: reserved 0

debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1

debug2: kex_parse_kexinit: ssh-rsa,ssh-dss

debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-
cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr

debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-
cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr

debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96

debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96

debug2: kex_parse_kexinit: none,zlib@openssh.com

debug2: kex_parse_kexinit: none,zlib@openssh.com

debug2: kex_parse_kexinit:

debug2: kex_parse_kexinit:

debug2: kex_parse_kexinit: first_kex_follows 0

debug2: kex_parse_kexinit: reserved 0

debug2: mac_setup: found hmac-md5

debug1: kex: server->client aes128-ctr hmac-md5 none

debug2: mac_setup: found hmac-md5

debug1: kex: client->server aes128-ctr hmac-md5 none

debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<1024<8192) sent

debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP

debug2: dh_gen_key: priv key bits set: 118/256

debug2: bits set: 474/1024

debug1: SSH2_MSG_KEX_DH_GEX_INIT sent

debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY

debug2: no key of type 0 for host server3l

debug2: no key of type 2 for host server3l

debug1: read_passphrase: can't open /dev/tty: EDC5128I No such device. (errno2=0x056201A9)

debug1: permanently_drop_suid: 12345

fromdsn(OS.SHARE.COZ.SUPPORT.LIB(NWME))[N]: 1 records/80 bytes read; 8 bytes written in 0 milliseconds.
debug1: read_passphrase: can't open /dev/tty: EDC5128I No such device. (errno2=0x056201A9)

debug1: permanently_drop_suid: 12345

[21:46:11.963347] CoZLauncher[D]: <32> Killing child process CozAgent (33620411) with signal 15
[21:46:11.963504] CoZLauncher[N]: <32> id12345@server3l target command '<default shell>' ended with RC=0
CEE5205S The signal SIGTERM was received.
[21:46:11.971232] CoZLauncher: <33> CoZLauncher ended with RC=0
[/list]

usaajrm · Post by **usaajrm** » Tue Mar 15, 2011 12:42 pm

I've ran it a number of times with various logging options. It appears the agent process is started then is signaled to terminate. Just as if agent starts but does not read STDIN before terminting.
Any ideas to get us back on track would be appreciated. Thank you.

Post by **dovetail** » Wed Mar 16, 2011 3:33 pm

You mentioned that this problem started when you upgraded your version of Co:Z.

- What was the previous version?
- Did nothing else change? (Same version of IBM Ported Tools?)
- If you run the same job on the same system with the old version of Co:Z, how does it compare? (just change the STEPLIB and property that points to the Co:Z HFS directory)

usaajrm · Post by **usaajrm** » Wed Mar 16, 2011 3:39 pm

We upgraded from 1.6 to 1.8 on z/OS. I've tried going back, but all combinations resulted in the same error.
FOTS2212 PRIV_END: seteuid: EDC5157I An internal error has occurred. (errno2=0x0B7F02A4)

Post by **dovetail** » Wed Mar 16, 2011 4:13 pm

This is the error that you would get from IBM Ported Tools 1.2 if it were spawned in the same address space as Co:Z Launcher.

Starting in Ported Tools 1.2, the "ssh" binary has the APF extended attribute bit, and therefore it will not spawn in the same address space.

It appears to me that you have somehow lost the extended attribute "APF" bit on the IBM Ported Tools ssh command.

usaajrm · Post by **usaajrm** » Thu Mar 17, 2011 10:39 am

I'm getting closer. The z/os admin added the extended attribute bit. Now I'm getting a signal 15. Thanks for your patience. I really want this to work.

[15:01:47.496760] CoZLauncher[N]: version: 1.8.0 2011-02-03
[15:01:47.504667] CoZLauncher[N]: Copyright (C) Dovetailed Technologies, LLC. 2006. All rights reserved.
[15:01:47.504686] CoZLauncher[D]: target_user="nw29233", target_host="testbat3l", target_port="NULL"
[15:01:47.504719] CoZLauncher[D]: sysname=B012
[15:01:47.504728] CoZLauncher[D]: CoZLauncher process id=50397547. Parent pid=1
[15:01:47.504742] CoZLauncher[D]: region size requested = 32768K, Actual below/above limit = 8168K / 1132544K
[10:01:47.519855] CoZLauncher: Agent output WTO is ON
[10:01:47.519880] CoZLauncher: ssh tunnelling is ON
[10:01:47.519889] CoZLauncher[D]: server-path=/usr/local/coz/bin/cozserver
[10:01:47.519899] CoZLauncher[D]: server-ports=8040-8048
[10:01:47.519908] CoZLauncher[D]: ssh-path=/bin/ssh
[10:01:47.519916] CoZLauncher[D]: ssh-tunnel=true
[10:01:47.519924] CoZLauncher[D]: ssh-shareas=YES
[10:01:47.519932] CoZLauncher[D]: agent-path=/opt/dovetail/coz/bin/cozagent
[10:01:47.519940] CoZLauncher[D]: agent-output-wto=true
[10:01:47.519948] CoZLauncher[D]: ssh-options=-vv
[10:01:47.519956] CoZLauncher[D]: agent-options=-LD,t
[10:01:47.519964] CoZLauncher[D]: target-env-COZ_LOG=D,t
[10:01:47.525346] CoZLauncher[D]: Server port range: 8040-8048
[10:01:47.525370] CoZLauncher[D]: Attempting to start socket listener on port 8040
[10:01:47.649494] CoZLauncher: CoZServer listener socket bound to: 127.0.0.1:8040
[10:01:47.649922] CoZLauncher[D]: server_cmd...
/usr/local/coz/bin/cozserver -sockfd 3
[10:01:47.652456] CoZLauncher[D]: Started CoZServer process: 83951982
[10:01:47.657783] CoZLauncher[D]: arg[3] = '-vv'
[10:01:47.657815] CoZLauncher[D]: arg[0] = '-LD,t'
[10:01:47.657826] CoZLauncher[D]: agent_cmd...
/bin/ssh -l nw29233 -vv -R 8040:127.0.0.1:8040 testbat3l /opt/dovetail/coz/bin/cozagent -LD,t
[10:01:47.661377] CoZLauncher[D]: Started CoZAgent process: 83951967
[10:01:47.661581] CoZLauncher[D]: About to start target command: ''
[10:01:47.669226] CoZLauncher[D]: serverStderrThread completed
[10:01:47.670062] CoZLauncher[D]: CoZServer (83951982) ended with RC=0
[10:01:47.670120] CoZLauncher[D]: Signalling agent process
[10:01:47.670129] CoZLauncher[D]: Sleep before Killing child process CozAgent (83951967)
[10:01:47.870424] CoZLauncher[D]: First agent message received:
OpenSSH_5.0p1, OpenSSL 0.9.8k 25 Mar 2009
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: zsshSmfSetConnSmfStatus: SMF status is 0
debug1: Rhosts Authentication disabled, originating port will not be trusted.
debug2: ssh_connect: needpriv 0
debug1: Connecting to testbat3l [10.160.2.236] port 22.
debug1: Connection established.
debug1: identity file /u/nw29233/.ssh/id_rsa type -1
debug2: key_type_from_name: unknown key type '-----BEGIN'
debug2: key_type_from_name: unknown key type '-----END'
debug1: identity file /u/nw29233/.ssh/id_dsa type 2
debug1: Remote protocol version 2.0, remote software version OpenSSH_4.3
debug1: match: OpenSSH_4.3 pat OpenSSH*
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_5.0
debug2: fd 3 setting O_NONBLOCK
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group1
4-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast1
28-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast1
28-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96
,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96
,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib@openssh.com,zlib
debug2: kex_parse_kexinit: none,zlib@openssh.com,zlib
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-
cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-
cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib@openssh.com
debug2: kex_parse_kexinit: none,zlib@openssh.com
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug2: mac_setup: found hmac-md5
debug1: kex: server->client aes128-ctr hmac-md5 none
debug2: mac_setup: found hmac-md5
debug1: kex: client->server aes128-ctr hmac-md5 none
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<1024<8192) sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
debug2: dh_gen_key: priv key bits set: 132/256
debug2: bits set: 521/1024
debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
debug1: Host 'testbat3l' is known and matches the RSA host key.
debug1: Found key in /u/nw29233/.ssh/known_hosts:2
debug2: bits set: 541/1024
debug1: ssh_rsa_verify: signature correct
debug2: kex_derive_keys
debug2: set_newkeys: mode 1
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug2: set_newkeys: mode 0
debug1: SSH2_MSG_NEWKEYS received
debug1: SSH2_MSG_SERVICE_REQUEST sent
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug2: key: /u/nw29233/.ssh/id_rsa (0)
debug2: key: /u/nw29233/.ssh/id_dsa (3B8EF0B0)
=== Help ensure information systems are used solely for authorized purposes.
===
=== This is a business information system for authorized use only.
=== Unauthorized use and other violations of company policy may result in
=== corrective action, up to and including immediate termination, and/or
=== criminal prosecution. Use of this system and all files on it may be
=== monitored, copied, and disclosed at any time, by USAA.
===
=== By using this system you agree to the above terms and conditions.
===
=== Please do your part to protect USAA's resources.
debug1: Authentications that can continue: publickey,password,keyboard-interactive
debug1: Next authentication method: publickey
debug1: Trying private key: /u/nw29233/.ssh/id_rsa
debug1: Offering public key: /u/nw29233/.ssh/id_dsa
debug2: we sent a publickey packet, wait for reply
debug1: Server accepts key: pkalg ssh-dss blen 434
debug2: input_userauth_pk_ok: fp 5d:86:e7:23:22:86:7f:ae:10:ba:77:0b:d3:f3:3f:35 debug1: read PEM private key done: type DSA
debug1: Authentication succeeded (publickey).
debug1: Remote connections from LOCALHOST:8040 forwarded to local address 127.0.0.1:8040
debug2: fd 4 setting O_NONBLOCK
debug2: fd 5 setting O_NONBLOCK
debug2: fd 6 setting O_NONBLOCK
debug1: channel 0: new [client-session]
debug2: channel 0: send open
debug1: Entering interactive session
debug1: remote forward success for: listen 8040, connect 127.0.0.1:8040
[10:01:48.670947] CoZLauncher[D]: Killing child process CozAgent (83951967) with signal 15
[10:01:48.671251] CoZLauncher[N]: nw29233@testbat3l target command '<default shell>' ended with RC=0
debug1: channel 0: free: client-session, nchannels
debug1: fd 0 clearing O_NONBLOCK
debug1: fd 1 clearing O_NONBLOCK
debug1: fd 2 clearing O_NONBLOCK
[10:01:48.673094] CoZLauncher: CoZLauncher ended with RC=0

Post by **dovetail** » Thu Mar 17, 2011 10:46 am

I don't see a problem in this trace. The Debug-level message that you are seeing regarding the signal is normal.

usaajrm · Post by **usaajrm** » Thu Mar 17, 2011 11:49 am

I'm getting a connection refused now. Where was it documented where the ssh server can be configured for reverse forwarding?

Post by **dovetail** » Thu Mar 17, 2011 12:28 pm

(A refused ssh connection would be a separate issue than the previous log in this thread.)

Background: Co:Z Launcher (when "ssh-tunnel=true") starts an ssh session to the target machine and sets up reverse port fowarding from the target machine back to the Co:Z Launcher job. Reverse port forwarding is not required when ssh tunneling of dataset connections is disabled, which is the preferred mode when running over a secure network, like a hipersocket, zBX IEDN, or even within a secure data center network. The default which is ssh-tunnel=true will encrypt fromdsn/todsn connections from the target process back into the Co:Z Launcher job step by tunneling them through the ssh connection using reverse port forwarding.

Port forwarding permissions are a configuration option of the target SSHD server. If you are using OpenSSH on the target, then this is configured by setting "AllowTcpForwarding" to yes (which is the default). See "man sshd" on your target machine for details.

But a server that doesn't allow port forwarding will not usually cause a connection to be refused. Typically, it will allow the connection but refuse to set up the reverse forwarder.

usaajrm · Post by **usaajrm** » Thu Mar 17, 2011 2:55 pm

After the extended attribute was applied to sshd on z/OS, we got pass the seteuid and internal error. It now looks like ports 8040-8048 from our linux server to z/OS are blocked. We have requested them to be open. I can see in the logging that logon is working, starting the agent, reading of stdin. But I get to results back to stdout and the connection refused. I believe this was due to the firewall team made some broad changes. Hopefully, this is it. Thank you.

[18:53:38.836169] CoZLauncher[N]: version: 1.8.0 2011-02-03
[18:53:38.847369] CoZLauncher[N]: Copyright (C) Dovetailed Technologies, LLC. 2006. All rights reserved.
[18:53:38.847392] CoZLauncher[D]: target_user="id12345", target_host="server3", target_port="NULL"
[18:53:38.847408] CoZLauncher[T]: -> CoZLauncher()
[18:53:38.847431] CoZLauncher[D]: sysname=X011
[18:53:38.847437] CoZLauncher[T]: <- CoZLauncher()
[18:53:38.847448] CoZLauncher[T]: -> run()
[18:53:38.847456] CoZLauncher[D]: CoZLauncher process id=84017498. Parent pid=1
[18:53:38.847465] CoZLauncher[T]: -> logRegionSize()
[18:53:38.847473] CoZLauncher[D]: region size requested = 32768K, Actual below/above limit = 8168K / 1146880K
[18:53:38.847484] CoZLauncher[T]: <- logRegionSize()
[18:53:38.847497] CoZLauncher[T]: -> loadEtcInitOptionsEnv()
[18:53:38.848089] CoZLauncher[T]: loadEtcInitOptionsEnv: TZ=CST6CDT
[13:53:38.848233] CoZLauncher[T]: <- loadEtcInitOptionsEnv()
[13:53:38.848248] CoZLauncher[T]: -> loadConfiguration()
[13:53:38.861567] CoZLauncher: Agent output WTO is ON
[13:53:38.861586] CoZLauncher: ssh tunnelling is ON
[13:53:38.861594] CoZLauncher[D]: server-path=/usr/local/coz/bin/cozserver
[13:53:38.861603] CoZLauncher[D]: server-ports=8040-8048
[13:53:38.861611] CoZLauncher[D]: ssh-path=/bin/ssh
[13:53:38.861619] CoZLauncher[D]: ssh-tunnel=true
[13:53:38.861627] CoZLauncher[D]: ssh-shareas=YES
[13:53:38.861638] CoZLauncher[D]: agent-path=/opt/dovetail/coz/bin/cozagent [13:53:38.861646] CoZLauncher[D]: agent-output-wto=true
[13:53:38.861654] CoZLauncher[D]: ssh-options=-vv
[13:53:38.861662] CoZLauncher[D]: agent-options=-LT,t
[13:53:38.861670] CoZLauncher[D]: target-env-COZ_LOG=T,t
[13:53:38.861678] CoZLauncher[T]: <- loadConfiguration()
[13:53:38.861686] CoZLauncher[T]: -> setServerEnvironment()
[13:53:38.861694] CoZLauncher[T]: -> loadEtcInitOptionsEnv()
[13:53:38.861978] CoZLauncher[T]: loadEtcInitOptionsEnv: TZ=CST6CDT
[13:53:38.862075] CoZLauncher[T]: <- loadEtcInitOptionsEnv()
[13:53:38.862087] CoZLauncher[T]: <- setServerEnvironment()
[13:53:38.862098] CoZLauncher[T]: -> generateAuthToken()
[13:53:38.864377] CoZLauncher[T]: <- generateAuthToken()
[13:53:38.864392] CoZLauncher[T]: -> determineServerPort()
[13:53:38.864408] CoZLauncher[D]: Server port range: 8040-8048
[13:53:38.864417] CoZLauncher[D]: Attempting to start socket listener on port 8040
[13:53:38.864428] CoZLauncher[T]: -> startSocketListener(host=127.0.0.1, port=8040)
[13:53:38.924254] CoZLauncher: CoZServer listener socket bound to: 127.0.0.1:8040
[13:53:38.924723] CoZLauncher[T]: <- startSocketListener(listensock=0)
[13:53:38.924754] CoZLauncher[T]: <- determineServerPort()
[13:53:38.924763] CoZLauncher[T]: -> launchServer()
[13:53:38.924771] CoZLauncher[T]: -> buildServerCommand()
[13:53:38.924783] CoZLauncher[D]: server_cmd...
/usr/local/coz/bin/cozserver -sockfd 3
[13:53:38.924800] CoZLauncher[T]: <- buildServerCommand()
[13:53:38.924810] CoZLauncher[T]: -> spawnServer()
[13:53:38.924903] CoZLauncher[T]: server fd_map[-1,-1,2,0]
[13:53:38.924915] CoZLauncher[T]: server_stderr_fd=1
[13:53:38.927016] CoZLauncher[D]: Started CoZServer process: 131407
[13:53:38.927049] CoZLauncher[T]: <- spawnServer()
[13:53:38.932068] CoZLauncher[T]: <- launchServer()
[13:53:38.932095] CoZLauncher[T]: -> launchAgent()
[13:53:38.932108] CoZLauncher[T]: -> buildAgentCommand()
[13:53:38.932117] CoZLauncher[T]: -> parseSshOptions()
[13:53:38.932127] CoZLauncher[D]: arg[3] = '-vv'
[13:53:38.932135] CoZLauncher[T]: <- parseSshOptions()
[13:53:38.932145] CoZLauncher[T]: -> parseCommand()
[13:53:38.932155] CoZLauncher[D]: arg[0] = '-LT,t'
[13:53:38.932165] CoZLauncher[T]: <- parseCommand(nargs=1)
[13:53:38.932176] CoZLauncher[D]: agent_cmd...
/bin/ssh -l id12345 -vv -R 8040:127.0.0.1:8040 server3 /opt/dovetail/coz/bin/cozagent -LT,t
[13:53:38.932684] CoZLauncher[T]: <- buildAgentCommand()
[13:53:38.932693] CoZLauncher[T]: -> spawnAgent()
[13:53:38.932805] CoZLauncher[T]: agent_fd_map[0,4,6]
[13:53:38.932816] CoZLauncher[T]: agent_fds[2,3,5]
[13:53:38.933892] CoZLauncher[T]: -> serverStderrThread()
[13:53:38.937036] CoZLauncher[D]: Started CoZAgent process: 131421
[13:53:38.937083] CoZLauncher[T]: <- spawnAgent()
[13:53:38.937092] CoZLauncher[T]: agent FDS=[2,3,5]
[13:53:38.937240] CoZLauncher[D]: About to start target command: ''
[13:53:38.938138] CoZLauncher[D]: serverStderrThread completed
[13:53:38.939894] CoZLauncher[T]: <- launchAgent()
[13:53:38.939911] CoZLauncher[T]: -> waitForChildren()
[13:53:38.939982] CoZLauncher[T]: -> waitStatusServer()
[13:53:38.939990] CoZLauncher[D]: CoZServer (131407) ended with RC=0
[13:53:38.939999] CoZLauncher[T]: <- waitStatusServer()
[13:53:38.940039] CoZLauncher[D]: Signalling agent process
[13:53:38.940047] CoZLauncher[D]: Sleep before Killing child process CozAgent (131421)
[13:53:38.940423] CoZLauncher[T]: -> agentStderrThread()
[13:53:38.940730] CoZLauncher[T]: -> agentStdoutThread()
[13:53:38.943807] CoZLauncher[T]: <- serverStderrThread()
[13:53:38.945541] CoZLauncher[T]: -> agentStdinThread()
[13:53:39.151182] CoZLauncher[D]: First agent message received:
OpenSSH_5.0p1, OpenSSL 0.9.8k 25 Mar 2009
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: zsshSmfSetConnSmfStatus: SMF status is 0
debug1: Rhosts Authentication disabled, originating port will not be trusted.
debug2: ssh_connect: needpriv 0
debug1: Connecting to server3 [15.16.2.323] port 22.
debug1: Connection established.
debug1: identity file /u/id12345/.ssh/id_rsa type -1
debug2: key_type_from_name: unknown key type '-----BEGIN'
debug2: key_type_from_name: unknown key type '-----END'
debug1: identity file /u/id12345/.ssh/id_dsa type 2
debug1: Remote protocol version 2.0, remote software version OpenSSH_4.3
debug1: match: OpenSSH_4.3 pat OpenSSH*
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_5.0
debug2: fd 3 setting O_NONBLOCK
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group1
4-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast1
28-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast1
28-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96
,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96
,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib@openssh.com,zlib
debug2: kex_parse_kexinit: none,zlib@openssh.com,zlib
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-
cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-
cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib@openssh.com
debug2: kex_parse_kexinit: none,zlib@openssh.com
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug2: mac_setup: found hmac-md5
debug1: kex: server->client aes128-ctr hmac-md5 none
debug2: mac_setup: found hmac-md5
debug1: kex: client->server aes128-ctr hmac-md5 none
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<1024<8192) sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
debug2: dh_gen_key: priv key bits set: 137/256
debug2: bits set: 524/1024
debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
debug1: Host 'server3' is known and matches the RSA host key.
debug1: Found key in /u/id12345/.ssh/known_hosts:2
debug2: bits set: 504/1024
debug1: ssh_rsa_verify: signature correct
debug2: kex_derive_keys
debug2: set_newkeys: mode 1
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug2: set_newkeys: mode 0
debug1: SSH2_MSG_NEWKEYS received
debug1: SSH2_MSG_SERVICE_REQUEST sent
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug2: key: /u/id12345/.ssh/id_rsa (0)
debug2: key: /u/id12345/.ssh/id_dsa (3AAEF0B0)
=== Help ensure information systems are used solely for authorized purposes.
===
=== This is a business information system for authorized use only.
=== Unauthorized use and other violations of company policy may result in
=== corrective action, up to and including immediate termination, and/or
=== criminal prosecution. Use of this system and all files on it may be
=== monitored, copied, and disclosed at any time, by USAA.
===
=== By using this system you agree to the above terms and conditions.
===
=== Please do your part to protect USAA's resources.

debug1: Authentications that can continue: publickey,password,keyboard-interactive
debug1: Next authentication method: publickey
debug1: Trying private key: /u/id12345/.ssh/id_rsa
debug1: Offering public key: /u/id12345/.ssh/id_dsa
debug2: we sent a publickey packet, wait for reply
debug1: Server accepts key: pkalg ssh-dss blen 434
debug2: input_userauth_pk_ok: fp 5d:86:e7:23:22:86:7f:ae:10:ba:77:0b:d3:f3:3f:35 debug1: read PEM private key done: type DSA
debug1: Authentication succeeded (publickey).
debug1: Remote connections from LOCALHOST:8040 forwarded to local address 127.0.0.1:8040
debug2: fd 4 setting O_NONBLOCK
debug2: fd 5 setting O_NONBLOCK
debug2: fd 6 setting O_NONBLOCK
debug1: channel 0: new [client-session]
debug2: channel 0: send open
debug1: Entering interactive session.
debug1: remote forward success for: listen 8040, connect 127.0.0.1:8040
debug2: callback start
debug2: client_session2_setup: id 0
debug1: Sending command: /opt/dovetail/coz/bin/cozagent -LT,t
debug2: channel 0: request exec confirm 0
debug2: fd 3 setting TCP_NODELAY
debug2: callback done
debug2: channel 0: open confirm rwindow 0 rmax 32768
debug2: channel 0: rcvd adjust 2097152
debug2: channel 0: rcvd ext data 40
cozagent[N]: version: 1.0.11 2010-10-27
debug2: channel 0: written 40 to efd 6
debug2: channel 0: rcvd ext data 200
debug2: channel 0: rcvd ext data 164
debug2: channel 0: rcvd ext data 87
debug2: channel 0: rcvd ext data 179
debug2: channel 0: rcvd ext data 119
debug2: channel 0: rcvd ext data 59
debug2: channel 0: rcvd ext data 327
[13:53:40.218563] cozagent: version: 1.0.11 2010-10-27
[13:53:40.218635] cozagent: Copyright (C) Dovetailed Technologies, LLC. 2006. All rights reserved.
[13:53:40.218640] cozagent[T]: -> run()
[13:53:40.218646] cozagent[T]: -> initialize()
[13:53:40.218652] cozagent[T]: -> configurePath()
[13:53:40.218660] cozagent[D]: cozagent dir: /opt/dovetail/coz/bin
[13:53:40.218673] cozagent[D]: cwd: /home/id12345
[13:53:40.218685] cozagent[D]: PATH:
[13:53:40.218691] cozagent[D]: /usr/local/bin
[13:53:40.218696] cozagent[D]: /bin
[13:53:40.218700] cozagent[D]: /usr/bin
[13:53:40.218704] cozagent[D]: /opt/dovetail/coz/bin
[13:53:40.218714] cozagent[T]: <- configurePath()
[13:53:40.218719] cozagent[D]: Waiting for configuration commands...
[13:53:40.218744] cozagent[T]: -> setEnvironmentVariable()
[13:53:40.218753] cozagent[D]: Set environment variable: 'COZ_SERVER_HOST'
[13:53:40.218758] cozagent[T]: <- setEnvironmentVariable()
[13:53:40.218763] cozagent[T]: -> setEnvironmentVariable()
[13:53:40.218770] cozagent[D]: Set environment variable: 'COZ_SERVER_PORT'
[13:53:40.218775] cozagent[T]: <- setEnvironmentVariable()
debug2: channel 0: written 1135 to efd 6
debug2: channel 0: rcvd ext data 318
debug2: channel 0: rcvd ext data 214
debug2: channel 0: rcvd ext data 83
debug2: channel 0: rcvd ext data 50
debug2: channel 0: rcvd ext data 110
debug2: channel 0: rcvd ext data 107
debug2: channel 0: rcvd ext data 56
debug2: channel 0: rcvd ext data 109
debug2: channel 0: rcvd ext data 56
debug2: channel 0: rcvd ext data 109
debug2: channel 0: rcvd ext data 52
debug2: channel 0: rcvd ext data 71
debug2: channel 0: rcvd ext data 213
debug2: channel 0: rcvd ext data 188
debug2: channel 0: rcvd ext data 68
debug1: client_input_channel_open: ctype forwarded-tcpip rchan 3 win 2097152 max 32768
debug1: client_request_forwarded_tcpip: listen localhost port 8040, originator 127.0.0.1 port 11447
debug2: fd 7 setting O_NONBLOCK
debug2: fd 7 setting TCP_NODELAY
debug1: channel 1: new [127.0.0.1]
debug1: confirm forwarded-tcpip
[13:53:40.218780] cozagent[T]: -> setEnvironmentVariable()
[13:53:40.218786] cozagent[D]: Set environment variable: 'COZ_AUTH_TOKEN'
[13:53:40.218790] cozagent[T]: <- setEnvironmentVariable()
[13:53:40.218795] cozagent[T]: -> setEnvironmentVariable()
[13:53:40.218801] cozagent[D]: Set environment variable: 'COZ_LOG'
[13:53:40.218806] cozagent[T]: <- setEnvironmentVariable()
[13:53:40.218812] cozagent[D]: target_command='NULL'
[13:53:40.218816] cozagent[T]: <- initialize()
[13:53:40.218820] cozagent[T]: -> startTargetProgram()
[13:53:40.219065] cozagent[D]: getpwuid(geteuid()) pw=0x4179d8, pw_shell=/bin/bash
[13:53:40.219360] cozagent[D]: target_pid = 17981
[13:53:40.219383] cozagent[T]: <- startTargetProgram()
[13:53:40.219390] cozagent[T]: -> startStdinDDReader()
[13:53:40.219642] cozagent[D]: stdin_dd_pid = 17982
[13:53:40.219655] cozagent[T]: <- startStdinDDReader()
[13:53:40.219660] cozagent[T]: -> startStdoutDDWriter()
[13:53:40.219918] cozagent[D]: stdout_dd_pid = 17983
[13:53:40.219931] cozagent[T]: <- startStdoutDDWriter()
[13:53:40.219936] cozagent[T]: -> startStderrDDWriter()
[13:53:40.220161] cozagent[D]: stderr_dd_pid = 17984
[13:53:40.220181] cozagent[T]: <- startStderrDDWriter()
[13:53:40.220205] cozagent[T]: -> waitForChildren()
[13:53:40.221556] fromdsn-client(17982): version: 1.0.11 2010-10-27
[13:53:40.221642] fromdsn-client(17982)[T]: -> exec(offset=2, nargs=1)
[13:53:40.221654] fromdsn-client(17982)[T]: exec: cmd_arg[0] = fromdsn
[13:53:40.221659] fromdsn-client(17982)[D]: cmd_arg[1] = //DD:STDIN
[13:53:40.221666] fromdsn-client(17982)[T]: -> startSocketConnection()
[13:53:40.221672] fromdsn-client(17982)[D]: Using getaddrinfo() to start connection to server 127.0.0.1 at port 8040
[13:53:40.221710] fromdsn-client(17982)[T]: -> connectWithTimeout()
debug2: channel 0: written 1804 to efd 6
debug1: channel 1: not connected: EDC8128I Connection refused. (errno2=0x05FC0119)
debug2: channel 1: zombie
debug2: channel 1: garbage collecting
debug1: channel 1: free: 127.0.0.1, nchannels 2
debug2: channel 0: rcvd ext data 281
debug2: channel 0: rcvd ext data 83
debug2: channel 0: rcvd ext data 69
debug2: channel 0: rcvd ext data 197
debug2: channel 0: rcvd ext data 251
debug2: channel 0: rcvd ext data 208
debug2: channel 0: rcvd ext data 194
debug2: channel 0: rcvd ext data 66
[13:53:40.221778] fromdsn-client(17982)[T]: <- connectWithTimeout(true)
[13:53:40.221786] fromdsn-client(17982)[T]: <- startSocketConnection()
[13:53:40.221791] fromdsn-client(17982)[T]: -> sendControlPackets()
[13:53:40.221797] fromdsn-client(17982)[T]: -> sendClientInfoPacket()
[13:53:40.221879] fromdsn-client(17982)[D]: clientCodePage 'UTF-8' (via setlocale)
[13:53:40.221852] todsn-client(17983): version: 1.0.11 2010-10-27
[13:53:40.221947] todsn-client(17983)[T]: -> exec(offset=2, nargs=2)
[13:53:40.221959] todsn-client(17983)[T]: exec: cmd_arg[0] = todsn
[13:53:40.221964] todsn-client(17983)[D]: cmd_arg[1] = -z
[13:53:40.221970] todsn-client(17983)[D]: cmd_arg[2] = //DD:STDOUT
[13:53:40.221983] todsn-client(17983)[T]: -> startSocketConnection()
[13:53:40.221989] todsn-client(17983)[D]: Using getaddrinfo() to start connection to server 127.0.0.1 at port 8040
[13:53:40.221936] todsn-client(17984): version: 1.0.11 2010-10-27
[13:53:40.222011] todsn-client(17984)[T]: -> exec(offset=2, nargs=2)
[13:53:40.222021] todsn-client(17984)[T]: exec: cmd_arg[0] = todsn
[13:53:40.222027] todsn-client(17984)[D]: cmd_arg[1] = -z
[13:53:40.222033] todsn-client(17984)[D]: cmd_arg[2] = //DD:STDERR
[13:53:40.222040] todsn-client(17984)[T]: -> startSocketConnection()
[13:53:40.222040] todsn-client(17983)[T]: -> connectWithTimeout()
debug2: channel 0: written 1349 to efd 6
debug2: channel 0: rcvd ext data 181
debug1: client_input_channel_open: ctype forwarded-tcpip rchan 4 win 2097152 max 32768
debug1: client_request_forwarded_tcpip: listen localhost port 8040, originator 127.0.0.1 port 11448
debug2: fd 7 setting O_NONBLOCK
debug2: fd 7 setting TCP_NODELAY
debug1: channel 1: new [127.0.0.1]
debug1: confirm forwarded-tcpip
debug1: client_input_channel_open: ctype forwarded-tcpip rchan 5 win 2097152 max 32768
debug1: client_request_forwarded_tcpip: listen localhost port 8040, originator 127.0.0.1 port 11449
debug2: fd 8 setting O_NONBLOCK
debug2: fd 8 setting TCP_NODELAY
debug1: channel 2: new [127.0.0.1]
debug1: confirm forwarded-tcpip
debug2: channel 0: rcvd ext data 273
debug2: channel 0: rcvd ext data 273
debug2: channel 0: rcvd ext data 162
debug2: channel 0: rcvd ext data 81
debug2: channel 0: rcvd ext data 329
debug2: channel 0: rcvd ext data 81
debug2: channel 0: rcvd ext data 549
debug2: channel 0: rcvd ext data 167
debug2: channel 0: rcvd ext data 158
debug2: channel 0: rcvd ext data 193
debug2: channel 0: rcvd ext data 158
debug2: channel 0: rcvd ext data 61
debug2: channel 0: rcvd ext data 66
debug2: channel 0: rcvd ext data 188
debug2: channel 0: rcvd ext data 127
debug2: channel 0: rcvd ext data 135
debug2: channel 0: rcvd ext data 126
[13:53:40.222045] todsn-client(17984)[D]: Using getaddrinfo() to start connection to server 127.0.0.1 at port 8040
[13:53:40.222087] todsn-client(17984)[T]: -> connectWithTimeout()
[13:53:40.222132] todsn-client(17983)[T]: <- connectWithTimeout(true)
[13:53:40.222142] todsn-client(17983)[T]: <- startSocketConnection()
[13:53:40.222147] todsn-client(17983)[T]: -> sendControlPackets()
[13:53:40.222154] todsn-client(17983)[T]: -> sendClientInfoPacket()
[13:53:40.222182] todsn-client(17984)[T]: <- connectWithTimeout(true)
[13:53:40.222191] todsn-client(17984)[T]: <- startSocketConnection()
[13:53:40.222196] todsn-client(17984)[T]: -> sendControlPackets()
[13:53:40.222204] todsn-client(17984)[T]: -> sendClientInfoPacket()
[13:53:40.222221] fromdsn-client(17982)[T]: sendClientInfoPacket: 31 of 31 bytes written
[13:53:40.222229] fromdsn-client(17982)[T]: <- sendClientInfoPacket()
[13:53:40.222229] todsn-client(17983)[D]: clientCodePage 'UTF-8' (via setlocale)
[13:53:40.222234] fromdsn-client(17982)[T]: -> sendIOConfigPacket()
[13:53:40.222248] fromdsn-client(17982)[T]: <- sendIOConfigPacket()
[13:53:40.222254] fromdsn-client(17982)[T]: -> sendAuthToken()
[13:53:40.222269] fromdsn-client(17982)[T]: <- sendAuthToken()
[13:53:40.222278] fromdsn-client(17982)[T]: -> sendCommandPacket()
[13:53:40.222280] todsn-client(17984)[D]: clientCodePage 'UTF-8' (via setlocale)
[13:53:40.222285] fromdsn-client(17982)[T]: sendCommandPacket: packet->payload.command="fromdsn '//DD:STDIN' " len=21
[13:53:40.222299] fromdsn-client(17982)[T]: <- sendCommandPacket()
[13:53:40.222305] fromdsn-client(17982)[T]: -> sendStreamBeginsPacket()
[13:53:40.222316] fromdsn-client(17982)[T]: <- sendStreamBeginsPacket()
[13:53:40.222322] fromdsn-client(17982)[T]: <- sendControlPackets()
[13:53:40.222329] fromdsn-client(17982)[T]: -> handleCmdIO()
[13:53:40.222352] fromdsn-client(17982)[T]: handleCmdIO: set STDOUT_FD to O_NONBLOCK
[13:53:40.222373] fromdsn-client(17982)[T]: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
[13:53:40.222379] fromdsn-client(17982)[T]: handleCmdIO: select()...
[13:53:40.222568] todsn-client(17983)[T]: sendClientInfoPacket: 31 of 31 bytes written
[13:53:40.222579] todsn-client(17983)[T]: <- sendClientInfoPacket()
[13:53:40.222585] todsn-client(17983)[T]: -> sendIOConfigPacket()
[13:53:40.222598] todsn-client(17983)[T]: <- sendIOConfigPacket()
[13:53:40.222604] todsn-client(17983)[T]: -> sendAuthToken()
[13:53:40.222614] todsn-client(17984)[T]: sendClientInfoPacket: 31 of 31 bytes written
[13:53:40.222622] todsn-client(17984)[T]: <- sendClientInfoPacket()
[13:53:40.222621] todsn-client(17983)[T]: <- sendAuthToken()
[13:53:40.222628] todsn-client(17984)[T]: -> sendIOConfigPacket()
[13:53:40.222628] todsn-client(17983)[T]: -> sendCommandPacket()
[13:53:40.222637] todsn-client(17983)[T]: sendCommandPacket: packet->payload.command="todsn '-z' '//DD:STDOUT' "
len=25 [13:53:40.222642] todsn-client(17984)[T]: <- sendIOConfigPacket()
[13:53:40.222649] todsn-client(17984)[T]: -> sendAuthToken()
[13:53:40.222652] todsn-client(17983)[T]: <- sendCommandPacket()
[13:53:40.222658] todsn-client(17983)[T]: -> sendStreamBeginsPacket()
[13:53:40.222666] todsn-client(17984)[T]: <- sendAuthToken()
[13:53:40.222673] todsn-client(17984)[T]: -> sendCommandPacket()
debug2: channel 0: written 3308 to efd 6
debug1: channel 1: not connected: EDC8128I Connection refused. (errno2=0x05FC0119)
debug2: channel 1: zombie
debug2: channel 1: garbage collecting
debug1: channel 1: free: 127.0.0.1, nchannels 3
debug1: channel 2: not connected: EDC8128I Connection refused. (errno2=0x0523011C)
debug2: channel 2: zombie
debug2: channel 2: garbage collecting
debug1: channel 2: free: 127.0.0.1, nchannels 2
debug2: channel 0: rcvd ext data 136
debug2: channel 0: rcvd ext data 123
debug2: channel 0: rcvd ext data 59
debug2: channel 0: rcvd ext data 65
debug2: channel 0: rcvd ext data 85
debug2: channel 0: rcvd ext data 70
debug2: channel 0: rcvd ext data 75
debug2: channel 0: rcvd ext data 70
debug2: channel 0: rcvd ext data 93
debug2: channel 0: rcvd ext data 66
debug2: channel 0: rcvd ext data 70
debug2: channel 0: rcvd ext data 952
debug2: channel 0: rcvd ext data 79
[13:53:40.222672] todsn-client(17983)[T]: <- sendStreamBeginsPacket()
[13:53:40.222679] todsn-client(17983)[T]: <- sendControlPackets()
[13:53:40.222681] todsn-client(17984)[T]: sendCommandPacket: packet->payload.command="todsn '-z' '//DD:STDERR' "
len=25
[13:53:40.222687] todsn-client(17983)[T]: -> handleCmdIO()
[13:53:40.222695] todsn-client(17984)[T]: <- sendCommandPacket()
[13:53:40.222700] todsn-client(17983)[T]: handleCmdIO: set STDIN_FD to O_NONBLOCK
[13:53:40.222702] todsn-client(17984)[T]: -> sendStreamBeginsPacket()
[13:53:40.222710] todsn-client(17983)[T]: handleCmdIO: FD_SET: STDIN_FD
[13:53:40.222715] todsn-client(17984)[T]: <- sendStreamBeginsPacket()
[13:53:40.222717] todsn-client(17983)[T]: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
[13:53:40.222721] todsn-client(17984)[T]: <- sendControlPackets()
[13:53:40.222724] todsn-client(17983)[T]: handleCmdIO: select()...
[13:53:40.222730] todsn-client(17984)[T]: -> handleCmdIO()
[13:53:40.222743] todsn-client(17984)[T]: handleCmdIO: set STDIN_FD to O_NONBLOCK
[13:53:40.222752] todsn-client(17984)[T]: handleCmdIO: FD_SET: STDIN_FD
[13:53:40.222758] todsn-client(17984)[T]: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
[13:53:40.222763] todsn-client(17984)[T]: handleCmdIO: select()...
[13:53:40.222769] todsn-client(17984)[T]: handleCmdIO: select() STDIN_FD...
[13:53:40.222779] todsn-client(17984)[T]: handleCmdIO: read 65 bytes from stdin
[13:53:40.222785] todsn-client(17984)[T]: handleCmdIO: select() fd_conn_snd...
[13:53:40.222799] todsn-client(17984)[T]: handleCmdIO: wrote 65 bytes to fd_conn_snd
[13:53:40.222805] todsn-client(17984)[T]: handleCmdIO: FD_SET: STDIN_FD
[13:53:40.222810] todsn-client(17984)[T]: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
[13:53:40.222815] todsn-client(17984)[T]: handleCmdIO: select()...
[13:53:40.235231] todsn-client(17984)[T]: handleCmdIO: select() STDIN_FD...
debug2: channel 0: written 1943 to efd 6
debug2: channel 0: rcvd ext data 570
debug2: channel 0: rcvd ext data 421
debug2: channel 0: rcvd ext data 70
debug2: channel 0: rcvd ext data 162
debug2: channel 0: rcvd ext data 245
debug2: channel 0: rcvd ext data 407
debug2: channel 0: rcvd ext data 326
debug2: channel 0: rcvd ext data 162
debug2: channel 0: rcvd ext data 245
debug2: channel 0: rcvd ext data 407
debug2: channel 0: rcvd ext data 326
debug2: channel 0: rcvd ext data 162
debug2: channel 0: rcvd ext data 652
debug2: channel 0: rcvd ext data 326
[13:53:40.235242] todsn-client(17984)[T]: handleCmdIO: read 20 bytes from stdin
[13:53:40.235248] todsn-client(17984)[T]: handleCmdIO: select() fd_conn_snd...
[13:53:40.235263] todsn-client(17984)[T]: handleCmdIO: wrote 20 bytes to fd_conn_snd
[13:53:40.235268] todsn-client(17984)[T]: handleCmdIO: FD_SET: STDIN_FD
[13:53:40.235273] todsn-client(17984)[T]: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
[13:53:40.235277] todsn-client(17984)[T]: handleCmdIO: select()...
[13:53:40.235285] todsn-client(17984)[T]: handleCmdIO: select() STDIN_FD...
[13:53:40.235293] todsn-client(17984)[T]: handleCmdIO: read 19 bytes from stdin
[13:53:40.235298] todsn-client(17984)[T]: handleCmdIO: select() fd_conn_snd...
[13:53:40.235310] todsn-client(17984)[T]: handleCmdIO: wrote 19 bytes to fd_conn_snd
[13:53:40.235315] todsn-client(17984)[T]: handleCmdIO: FD_SET: STDIN_FD
[13:53:40.235322] todsn-client(17984)[T]: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
[13:53:40.235327] todsn-client(17984)[T]: handleCmdIO: select()...
[13:53:40.236321] todsn-client(17984)[T]: handleCmdIO: select() STDIN_FD...
[13:53:40.236332] todsn-client(17984)[T]: handleCmdIO: read 20 bytes from stdin
[13:53:40.236337] todsn-client(17984)[T]: handleCmdIO: select() fd_conn_snd...
[13:53:40.236351] todsn-client(17984)[T]: handleCmdIO: wrote 20 bytes to fd_conn_snd
[13:53:40.236356] todsn-client(17984)[T]: handleCmdIO: FD_SET: STDIN_FD
[13:53:40.236361] todsn-client(17984)[T]: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
[13:53:40.236366] todsn-client(17984)[T]: handleCmdIO: select()...
[13:53:40.236372] todsn-client(17984)[T]: handleCmdIO: select() STDIN_FD...
[13:53:40.236379] todsn-client(17984)[T]: handleCmdIO: read 19 bytes from stdin
[13:53:40.236384] todsn-client(17984)[T]: handleCmdIO: select() fd_conn_snd...
[13:53:40.236397] todsn-client(17984)[T]: handleCmdIO: wrote 19 bytes to fd_conn_snd
[13:53:40.236402] todsn-client(17984)[T]: handleCmdIO: FD_SET: STDIN_FD
[13:53:40.236407] todsn-client(17984)[T]: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
[13:53:40.236412] todsn-client(17984)[T]: handleCmdIO: select()...
[13:53:40.237441] todsn-client(17984)[T]: handleCmdIO: select() STDIN_FD...
[13:53:40.237451] todsn-client(17984)[T]: handleCmdIO: read 20 bytes from stdin
[13:53:40.237457] todsn-client(17984)[T]: handleCmdIO: select() fd_conn_snd...
[13:53:40.237470] todsn-client(17984)[T]: handleCmdIO: wrote 20 bytes to fd_conn_snd
[13:53:40.237475] todsn-client(17984)[T]: handleCmdIO: FD_SET: STDIN_FD
[13:53:40.237481] todsn-client(17984)[T]: handleCmdIO: FD_SET: 0fd_conn_rcv, bytesToRead=4
[13:53:40.237485] todsn-client(17984)[T]: handleCmdIO: select()...
[13:53:40.237492] todsn-client(17984)[T]: handleCmdIO: select() STDIN_FD...
[13:53:40.237498] todsn-client(17984)[T]: handleCmdIO: read 19 bytes from stdin
[13:53:40.237503] todsn-client(17984)[T]: handleCmdIO: select() fd_conn_snd...
[13:53:40.237516] todsn-client(17984)[T]: handleCmdIO: wrote 19 bytes to fd_conn_snd
[13:53:40.237524] todsn-client(17984)[T]: handleCmdIO: FD_SET: STDIN_FD
[13:53:40.237529] todsn-client(17984)[T]: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
[13:53:40.237533] todsn-client(17984)[T]: handleCmdIO: select()...
[13:53:40.238596] todsn-client(17984)[T]: handleCmdIO: select() STDIN_FD...
[13:53:40.238608] todsn-client(17984)[T]: handleCmdIO: read 20 bytes from stdin
[13:53:40.238614] todsn-client(17984)[T]: handleCmdIO: select() fd_conn_snd...
[13:53:40.238628] todsn-client(17984)[T]: handleCmdIO: wrote 20 bytes to fd_conn_snd
[13:53:40.238633] todsn-client(17984)[T]: handleCmdIO: FD_SET: STDIN_FD
[13:53:40.238638] todsn-client(17984)[T]: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
[13:53:40.238643] todsn-client(17984)[T]: handleCmdIO: select()...
[13:53:40.238649] todsn-client(17984)[T]: handleCmdIO: select() STDIN_FD...
[13:53:40.238656] todsn-client(17984)[T]: handleCmdIO: read 19 bytes from stdin
[13:53:40.238660] todsn-client(17984)[T]: handleCmdIO: select() fd_conn_snd...
[13:53:40.238674] todsn-client(17984)[T]: handleCmdIO: wrote 19 bytes to fd_conn_snd
[13:53:40.238680] todsn-client(17984)[T]: handleCmdIO: FD_SET: STDIN_FD
[13:53:40.238684] todsn-client(17984)[T]: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
[13:53:40.238689] todsn-client(17984)[T]: handleCmdIO: select()...
debug2: channel 0: written 4481 to efd 6
[13:53:39.940227] CoZLauncher[D]: Killing child process CozAgent (131421) with signal 15
[13:53:39.940407] CoZLauncher[T]: -> waitStatusAgent()
[13:53:39.940426] CoZLauncher[N]: id12345@server3 target command '<default shell>' ended with RC=0
[13:53:39.940435] CoZLauncher[T]: <- waitStatusAgent()
[13:53:39.940462] CoZLauncher[T]: <- waitForChildren(rc=0)
[13:53:39.940474] CoZLauncher[T]: -> cleanup()
debug1: channel 0: free: client-session, nchannels 1
debug1: fd 0 clearing O_NONBLOCK
debug1: fd 1 clearing O_NONBLOCK
debug1: fd 2 clearing O_NONBLOCK
FOTS1437 Killed by signal 15.
[13:53:39.946627] CoZLauncher[D]: agentStderrThread completed
[13:53:39.946672] CoZLauncher[T]: <- agentStderrThread()
[13:53:39.947027] CoZLauncher[D]: agentStdoutThread completed
[13:53:39.947047] CoZLauncher[T]: <- agentStdoutThread()
[13:53:39.950253] CoZLauncher[T]: <- agentStdinThread()
[13:53:39.950509] CoZLauncher[T]: <- cleanup()
[13:53:39.950521] CoZLauncher: CoZLauncher ended with RC=0
[13:53:39.950529] CoZLauncher[T]: <- run()
[13:53:39.950538] CoZLauncher[T]: -> ~CoZLauncher()
[13:53:39.950558] CoZLauncher[T]: <- ~CoZLauncher()

Post by **dovetail** » Thu Mar 17, 2011 3:24 pm

I do not believe that this is a network firewall issue.

Since you have ssh-tunnel=true configured, the target end is attempting to open a socket *locally* to 127.0.0.1:8040 (on the target server), which is picked up by sshd. This is the reverse-forward connection that is tunneled by ssh back to the z/OS ssh client where it tries to open a port locally on z/OS to 127.0.0.1:8040. This last thing is what is failing:

debug1: channel 1: not connected: EDC8128I Connection refused

This message comes from the ssh client on z/OS. It is is unable to connect locally to the z/OS Co:Z Launcher job that is listening on port 8040 (you can see that it listens and binds to that on an early trace message).

So the problem is likely a security issue on z/OS that prevents the ssh client (on z/OS), running under the userid of the z/OS job, to open a local socket to the loopback adapter (127.0.0.1). You should check your security product logs, or perhaps the z/OS Comm Server syslog to see if there is an indication as to why this failed.

usaajrm · Post by **usaajrm** » Wed Mar 23, 2011 12:02 pm

Thank you. For those who follow this thread. The problem was the upgrade to 1.8. the z/OS admin's load failed and it was not noticed. This left the /usr/local/coz/bin directory with several empty files. One of the was the cozserver. We chased several rabbits until finding this. We've added checking the directory to the top of the list. Hence, the several threads on this forum with the same conclusion. Thanks dovetail.