search

DICE-UNC / jargon

Jargon core libraries
Other
28 stars 31 forks source link

PAM/SSL issues and slowness in workflow processing #27

Closed michael-conway closed 10 years ago

michael-conway commented 10 years ago

Hi ,

We run iRODS 3.3.1 instance for our VDJserver project here at TACC and use PAM/LDAP mechanism for authentication. We are facing an error described below randomly.

We are noticing different behaviors when using a particular workflow through the icommands vs. through Jargon ( VDJ server interface uses AGAVE API as a backend to talk to iRODS). The icommands are significantly faster than when repeating the same workflow using Jargon. For some reason, step 5 in my workflow can take up to 90 seconds when being run through Jargon. Also, during the 90 seconds, no body can access iRODS simultaneously. It just waits for the other process to complete. iRODS server logs are attached. We tested the same script with jargon on another iRODS instance where PAM/LDAP is not used for authentication and it runs with out any issues. When debugging it further, it looks like the Jargon SSL connection handling the PAM Auth code might be a possible venue for error. It looks like error codes in the log are related to client -server interaction problem.

Here’s what I’m doing:

1.) Create a directory called 2.) Set permissions on this directory 3.) Create a directory called /files 4.) Set permissions on this directory 5.) Create a directory called /analyses 6.) Set permissions on this directory

Note: I don’t think that setting the permissions affects the slow Jargon performance because I’ve noticed same behavior whether I run the aforementioned steps 1, 3, and 5 or whether I run all 6 steps.

We couldn’t trace the reason for this error. Can you guide us what might be an issue for this random error

michael-conway commented 10 years ago 

Jul 10 08:01:12 pid:84789 NOTICE: Agent process 2291 exited with status 0
Jul 10 08:01:12 pid:84789 NOTICE: Agent process 2440 started for puser=vdj and cuser=vdj from 146.6.176.42
Jul 10 08:01:12 pid:2440 NOTICE: rsAuthCheck user vdj#vdjZ
Jul 10 08:01:12 pid:2440 NOTICE: rsAuthResponse set proxy authFlag to 5, client authFlag to 5, user:vdj#vdjZ proxy:vdj client:vdj
Jul 10 08:01:12 pid:2440 NOTICE: readAndProcClientMsg: received disconnect msg from client
Jul 10 08:01:12 pid:2440 NOTICE: Agent exiting with status = 0
Jul 10 08:01:12 pid:84789 NOTICE: Agent process 2440 exited with status 0
Jul 10 08:01:12 pid:84789 NOTICE: Agent process 2442 started for puser=vdj and cuser=vdj from 146.6.176.42
Jul 10 08:01:12 pid:2442 NOTICE: rsAuthCheck user vdj#vdjZ
Jul 10 08:01:12 pid:2442 NOTICE: rsAuthResponse set proxy authFlag to 5, client authFlag to 5, user:vdj#vdjZ proxy:vdj client:vdj
Jul 10 08:01:12 pid:2442 NOTICE: recursiveFlag 0
Jul 10 08:01:12 pid:2442 NOTICE: readAndProcClientMsg: received disconnect msg from client
Jul 10 08:01:12 pid:2442 NOTICE: Agent exiting with status = 0
Jul 10 08:01:12 pid:84789 NOTICE: Agent process 2442 exited with status 0
Jul 10 08:01:12 pid:84789 NOTICE: Agent process 2444 started for puser=vdj and cuser=vdj from 146.6.176.42
Jul 10 08:01:12 pid:2444 NOTICE: rsAuthCheck user vdj#vdjZ
Jul 10 08:01:12 pid:2444 NOTICE: rsAuthResponse set proxy authFlag to 5, client authFlag to 5, user:vdj#vdjZ proxy:vdj client:vdj
Jul 10 08:01:12 pid:2444 NOTICE: readAndProcClientMsg: received disconnect msg from client
Jul 10 08:01:12 pid:2444 NOTICE: Agent exiting with status = 0
Jul 10 08:01:12 pid:84789 NOTICE: Agent process 2444 exited with status 0
Jul 10 08:01:12 pid:84789 NOTICE: Agent process 2446 started for puser=vdj and cuser=vdj from 146.6.176.42
Jul 10 08:01:12 pid:2446 NOTICE: rsAuthCheck user vdj#vdjZ
Jul 10 08:01:12 pid:2446 NOTICE: rsAuthResponse set proxy authFlag to 5, client authFlag to 5, user:vdj#vdjZ proxy:vdj client:vdj
Jul 10 08:01:12 pid:2446 NOTICE: recursiveFlag 0
Jul 10 08:01:12 pid:2446 NOTICE: readAndProcClientMsg: received disconnect msg from client
Jul 10 08:01:12 pid:2446 NOTICE: Agent exiting with status = 0
Jul 10 08:01:12 pid:84789 NOTICE: Agent process 2446 exited with status 0
Jul 10 08:01:12 pid:84789 NOTICE: Agent process 2448 started for puser=vdj and cuser=vdj from 146.6.176.42
Jul 10 08:01:12 pid:2448 NOTICE: rsAuthCheck user vdj#vdjZ
Jul 10 08:01:12 pid:2448 NOTICE: rsAuthResponse set proxy authFlag to 5, client authFlag to 5, user:vdj#vdjZ proxy:vdj client:vdj
Jul 10 08:01:12 pid:2448 NOTICE: readAndProcClientMsg: received disconnect msg from client
Jul 10 08:01:12 pid:2448 NOTICE: Agent exiting with status = 0
Jul 10 08:01:12 pid:84789 NOTICE: Agent process 2448 exited with status 0
Jul 10 08:01:12 pid:84789 NOTICE: Agent process 2450 started for puser=vdj and cuser=vdj from 146.6.176.42
Jul 10 08:01:12 pid:2450 NOTICE: rsAuthCheck user vdj#vdjZ
Jul 10 08:01:12 pid:2450 NOTICE: rsAuthResponse set proxy authFlag to 5, client authFlag to 5, user:vdj#vdjZ proxy:vdj client:vdj
Jul 10 08:01:12 pid:2450 NOTICE: recursiveFlag 0
Jul 10 08:01:12 pid:2450 NOTICE: readAndProcClientMsg: received disconnect msg from client
Jul 10 08:01:12 pid:2450 NOTICE: Agent exiting with status = 0
Jul 10 08:01:15 pid:84789 NOTICE: Agent process 2450 exited with status 0
Jul 10 08:01:15 pid:84789 NOTICE: Agent process 2453 started for puser=vdj and cuser=vdj from 129.114.60.167
Authenticated
Jul 10 08:01:16 pid:2453 ERROR: readMsgHeader:header read- read 0 bytes, expect 4, status = -4000
Jul 10 08:01:16 pid:2453 NOTICE: Agent exiting with status = -4000
Jul 10 08:01:16 pid:84789 NOTICE: Agent process 2456 started for puser=vdj and cuser=vdj from 129.114.60.167
Jul 10 08:01:16 pid:2456 NOTICE: rsAuthCheck user vdj
Jul 10 08:01:16 pid:2456 NOTICE: rsAuthResponse set proxy authFlag to 5, client authFlag to 5, user:vdj proxy:vdj client:vdj
Jul 10 08:01:16 pid:2456 NOTICE: recursiveFlag 0
Jul 10 08:01:16 pid:2456 NOTICE: recursiveFlag 0
Jul 10 08:01:16 pid:2456 NOTICE: readAndProcClientMsg: received disconnect msg from client
Jul 10 08:01:16 pid:2456 NOTICE: Agent exiting with status = 0
Jul 10 08:01:16 pid:84789 NOTICE: Agent process 2453 exited with status 256
Jul 10 08:01:16 pid:84789 NOTICE: Agent process 2456 exited with status 0
Jul 10 08:01:16 pid:84789 NOTICE: Agent process 2458 started for puser=vdj and cuser=vdj from 129.114.60.167
Authenticated
Jul 10 08:01:16 pid:2458 ERROR: readMsgHeader:header read- read 0 bytes, expect 4, status = -4000
Jul 10 08:01:16 pid:2458 NOTICE: Agent exiting with status = -4000
Jul 10 08:01:16 pid:84789 NOTICE: Agent process 2462 started for puser=vdj and cuser=vdj from 129.114.60.167
Jul 10 08:01:16 pid:2462 NOTICE: rsAuthCheck user vdj
Jul 10 08:01:16 pid:2462 NOTICE: rsAuthResponse set proxy authFlag to 5, client authFlag to 5, user:vdj proxy:vdj client:vdj
Jul 10 08:01:16 pid:2462 NOTICE: recursiveFlag 0
Jul 10 08:01:16 pid:2462 NOTICE: recursiveFlag 0
Jul 10 08:01:16 pid:2462 NOTICE: readAndProcClientMsg: received disconnect msg from client
Jul 10 08:01:16 pid:2462 NOTICE: Agent exiting with status = 0
Jul 10 08:01:16 pid:84789 NOTICE: Agent process 2458 exited with status 256
Jul 10 08:01:16 pid:84789 NOTICE: Agent process 2462 exited with status 0
Jul 10 08:01:16 pid:84789 NOTICE: Agent process 2464 started for puser=vdj and cuser=vdj from 129.114.60.167
Authenticated
Jul 10 08:01:17 pid:2464 ERROR: readMsgHeader:header read- read 0 bytes, expect 4, status = -4000
Jul 10 08:01:17 pid:2464 NOTICE: Agent exiting with status = -4000
Jul 10 08:01:17 pid:84789 NOTICE: Agent process 2467 started for puser=vdj and cuser=vdj from 129.114.60.167
Jul 10 08:01:17 pid:2467 NOTICE: rsAuthCheck user vdj
Jul 10 08:01:17 pid:2467 NOTICE: rsAuthResponse set proxy authFlag to 5, client authFlag to 5, user:vdj proxy:vdj client:vdj
Jul 10 08:01:17 pid:2467 NOTICE: recursiveFlag 1
Jul 10 08:01:17 pid:2467 NOTICE: recursiveFlag 1
Jul 10 08:01:17 pid:2467 NOTICE: readAndProcClientMsg: received disconnect msg from client
Jul 10 08:01:17 pid:2467 NOTICE: Agent exiting with status = 0
Jul 10 08:01:17 pid:84789 NOTICE: Agent process 2464 exited with status 256
Jul 10 08:01:17 pid:84789 NOTICE: Agent process 2467 exited with status 0
Jul 10 08:01:17 pid:84789 NOTICE: Agent process 2469 started for puser=vdj and cuser=vdj from 129.114.60.167
Authenticated
Jul 10 08:01:17 pid:2469 ERROR: readMsgHeader:header read- read 0 bytes, expect 4, status = -4000
Jul 10 08:01:17 pid:2469 NOTICE: Agent exiting with status = -4000
Jul 10 08:01:17 pid:84789 NOTICE: Agent process 2472 started for puser=vdj and cuser=vdj from 129.114.60.167
Jul 10 08:01:17 pid:2472 NOTICE: rsAuthCheck user vdj
Jul 10 08:01:17 pid:2472 NOTICE: rsAuthResponse set proxy authFlag to 5, client authFlag to 5, user:vdj proxy:vdj client:vdj
Jul 10 08:01:17 pid:2472 NOTICE: recursiveFlag 0
Jul 10 08:01:17 pid:2472 NOTICE: recursiveFlag 0
Jul 10 08:01:17 pid:2472 NOTICE: readAndProcClientMsg: received disconnect msg from client
Jul 10 08:01:17 pid:2472 NOTICE: Agent exiting with status = 0
Jul 10 08:01:17 pid:84789 NOTICE: Agent process 2469 exited with status 256
Jul 10 08:01:17 pid:84789 NOTICE: Agent process 2472 exited with status 0
Jul 10 08:01:17 pid:84789 NOTICE: Agent process 2474 started for puser=vdj and cuser=vdj from 129.114.60.167
Jul 10 08:01:17 pid:2474 ERROR: readMsgHeader:header read- read 0 bytes, expect 4, status = -4000
Jul 10 08:01:17 pid:2474 NOTICE: Agent exiting with status = -4000
Jul 10 08:02:56 pid:84789 ERROR: readMsgHeader:header read- read -115000 bytes, expect 4, status = -115107
Jul 10 08:02:56 pid:84789 NOTICE: readStartupPack: readMsgHeader error. status = -115107 status = -115107 SYS_SOCK_READ_TIMEDOUT, Transport endpoint is not connected
Jul 10 08:02:56 pid:84789 NOTICE: readStartupPack error from 129.114.60.167, status = -115107
Jul 10 08:02:56 pid:84789 NOTICE: Agent process 2487 started for puser=vdj and cuser=vdj from 129.114.60.167
Jul 10 08:02:56 pid:2487 NOTICE: rsAuthCheck user vdj
Jul 10 08:02:56 pid:2487 NOTICE: rsAuthResponse set proxy authFlag to 5, client authFlag to 5, user:vdj proxy:vdj client:vdj
Jul 10 08:02:56 pid:2487 NOTICE: recursiveFlag 1
Jul 10 08:02:56 pid:2487 NOTICE: recursiveFlag 1
Jul 10 08:02:56 pid:2487 NOTICE: readAndProcClientMsg: received disconnect msg from client
Jul 10 08:02:56 pid:2487 NOTICE: Agent exiting with status = 0
Jul 10 08:02:56 pid:84789 NOTICE: Agent process 2474 exited with status 256
Jul 10 08:02:56 pid:84789 NOTICE: Agent process 2487 exited with status 0
Jul 10 08:02:56 pid:84789 NOTICE: Agent process 2489 started for puser=vdj and cuser=vdj from 129.114.60.167
Jul 10 08:02:56 pid:84789 ERROR: readMsgHeader:header read- read -115000 bytes, expect 4, status = -115000
Jul 10 08:02:56 pid:84789 NOTICE: readStartupPack: readMsgHeader error. status = -115000 status = -115000 SYS_SOCK_READ_TIMEDOUT
Jul 10 08:02:56 pid:84789 NOTICE: readStartupPack error from 129.114.60.167, status = -115000
Authenticated
Jul 10 08:02:56 pid:2489 ERROR: readMsgHeader:header read- read 0 bytes, expect 4, status = -4000
Jul 10 08:02:56 pid:2489 NOTICE: Agent exiting with status = -4000
Jul 10 08:02:56 pid:84789 NOTICE: Agent process 2493 started for puser=vdj and cuser=vdj from 129.114.60.167
Jul 10 08:02:56 pid:2493 NOTICE: rsAuthCheck user vdj
Jul 10 08:02:56 pid:2493 NOTICE: rsAuthResponse set proxy authFlag to 5, client authFlag to 5, user:vdj proxy:vdj client:vdj
Jul 10 08:02:56 pid:2493 NOTICE: recursiveFlag 0
Jul 10 08:02:56 pid:2493 NOTICE: recursiveFlag 0
Jul 10 08:02:56 pid:2493 NOTICE: readAndProcClientMsg: received disconnect msg from client
Jul 10 08:02:56 pid:2493 NOTICE: Agent exiting with status = 0
Jul 10 08:02:57 pid:84789 ERROR: readMsgHeader:header read- read -115000 bytes, expect 4, status = -115107
Jul 10 08:02:57 pid:84789 NOTICE: readStartupPack: readMsgHeader error. status = -115107 status = -115107 SYS_SOCK_READ_TIMEDOUT, Transport endpoint is not connected
Jul 10 08:02:57 pid:84789 NOTICE: readStartupPack error from 129.114.60.167, status = -115107
Jul 10 08:02:57 pid:84789 ERROR: readMsgHeader:header read- read -115000 bytes, expect 4, status = -115107
Jul 10 08:02:57 pid:84789 NOTICE: readStartupPack: readMsgHeader error. status = -115107 status = -115107 SYS_SOCK_READ_TIMEDOUT, Transport endpoint is not connected
Jul 10 08:02:57 pid:84789 NOTICE: readStartupPack error from 129.114.60.167, status = -115107
Jul 10 08:02:57 pid:84789 ERROR: readMsgHeader:header read- read -115000 bytes, expect 4, status = -115000
Jul 10 08:02:57 pid:84789 NOTICE: readStartupPack: readMsgHeader error. status = -115000 status = -115000 SYS_SOCK_READ_TIMEDOUT
Jul 10 08:02:57 pid:84789 NOTICE: readStartupPack error from 129.114.60.167, status = -115000
michael-conway commented 10 years ago

-115000 = SYS_SOCK_READ_TIMEDOUT -115000

michael-conway commented 10 years ago

pushed to 4.0.2-SNAPSHOT and master branch

michael-conway commented 10 years ago

sent email, waiting site testing of potential fix