search

cyverse / gocommands

iRODS Command-line Tools written in Go
Other
29 stars 18 forks source link

`gocmd put` gives error in v0.7.12 #20

Closed jnimoth closed 10 months ago

jnimoth commented 10 months ago

Since the new version, I constantly get SYS_NOT_ALLOWED errors when using gocmd put for files and permission denied messages when trying to transfer folders.

Example for files:

$ gocommands/gocmd put --progress  usersvf_autocreated
/home/user/usersvf_autocreated                  ... done! [767B in 709ms]
iRODS Error: SYS_NOT_ALLOWED

Error Trace:
  - failed to perform parallel jobs:
    github.com/cyverse/gocommands/cmd/subcmd.processPutCommand
        /github/workspace/cmd/subcmd/put.go:140
  - failed to upload /home/user/usersvf_autocreated to /testrug/home/rdms-testers@rug.nl/usersvf_autocreated:
    github.com/cyverse/gocommands/cmd/subcmd.putOne.func1
        /github/workspace/cmd/subcmd/put.go:215
  - failed to replicate data object:
    github.com/cyverse/go-irodsclient/irods/fs.ReplicateDataObject
        /go/pkg/mod/github.com/cyverse/go-irodsclient@v0.12.16/irods/fs/data_object.go:1290
  - SYS_NOT_ALLOWED

And here once more with long debug log:

$ gocommands/gocmd put -d  usersvf_autocreated
DEBU[2023-10-23 13:08:47.742] use sessionID - 2219182                       function=ProcessCommonFlags package=flag
DEBU[2023-10-23 13:08:47.742] reading config file/dir - /home/user/.irods  function=LoadConfigFromFile package=commons
DEBU[2023-10-23 13:08:47.742] reading icommands environment file - /home/user/.irods/irods_environment.json  function=LoadConfigFromFile package=commons
DEBU[2023-10-23 13:08:47.743] reading environment file /home/user/.irods/irods_environment.json  function=Load package=icommands struct=ICommandsEnvironmentManager
DEBU[2023-10-23 13:08:47.743] reading environment password file /home/user/.irods/.irodsA  function=Load package=icommands struct=ICommandsEnvironmentManager
DEBU[2023-10-23 13:08:47.743] Connecting to rdms-test-icat.data.rug.nl:1247  function=Connect package=connection struct=IRODSConnection
DEBU[2023-10-23 13:08:47.746] Start up a connection with CS Negotiation     function=connectWithCSNegotiation package=connection struct=IRODSConnection
DEBU[2023-10-23 13:08:47.945] Start up CS Negotiation                       function=connectWithCSNegotiation package=connection struct=IRODSConnection
DEBU[2023-10-23 13:08:47.945] Client policy - CS_NEG_REQUIRE, server policy - CS_NEG_DONT_CARE  function=connectWithCSNegotiation package=connection struct=IRODSConnection
DEBU[2023-10-23 13:08:47.947] Start up SSL                                  function=sslStartup package=connection struct=IRODSConnection
DEBU[2023-10-23 13:08:47.960] Logging in using native authentication method  function=loginNative package=connection struct=IRODSConnection
DEBU[2023-10-23 13:08:48.013] testing connection                            function=NewIRODSSession package=session
DEBU[2023-10-23 13:08:48.013] Reuse an idle connection                      function=Get package=session struct=ConnectionPool
DEBU[2023-10-23 13:08:48.013] support parallel upload: true                 function=checkConnection package=session
DEBU[2023-10-23 13:08:48.013] Returning a connection                        function=Return package=session struct=ConnectionPool
DEBU[2023-10-23 13:08:48.014] Connecting to rdms-test-icat.data.rug.nl:1247  function=Connect package=connection struct=IRODSConnection
DEBU[2023-10-23 13:08:48.016] Start up a connection with CS Negotiation     function=connectWithCSNegotiation package=connection struct=IRODSConnection
DEBU[2023-10-23 13:08:48.211] Start up CS Negotiation                       function=connectWithCSNegotiation package=connection struct=IRODSConnection
DEBU[2023-10-23 13:08:48.211] Client policy - CS_NEG_REQUIRE, server policy - CS_NEG_DONT_CARE  function=connectWithCSNegotiation package=connection struct=IRODSConnection
DEBU[2023-10-23 13:08:48.213] Start up SSL                                  function=sslStartup package=connection struct=IRODSConnection
DEBU[2023-10-23 13:08:48.228] Logging in using native authentication method  function=loginNative package=connection struct=IRODSConnection
DEBU[2023-10-23 13:08:48.280] testing connection                            function=NewIRODSSession package=session
DEBU[2023-10-23 13:08:48.280] Reuse an idle connection                      function=Get package=session struct=ConnectionPool
DEBU[2023-10-23 13:08:48.280] support parallel upload: true                 function=checkConnection package=session
DEBU[2023-10-23 13:08:48.280] Returning a connection                        function=Return package=session struct=ConnectionPool
DEBU[2023-10-23 13:08:48.280] Reuse an idle connection                      function=Get package=session struct=ConnectionPool
DEBU[2023-10-23 13:08:48.280] start job run thread                          function=Start package=commons struct=ParallelJobManager
DEBU[2023-10-23 13:08:48.289] failed to commit transaction                  error=SYS_NO_API_PRIV function=endTransaction package=session struct=IRODSSession
DEBU[2023-10-23 13:08:48.295] Returning a connection                        function=Return package=session struct=ConnectionPool
DEBU[2023-10-23 13:08:48.295] Reuse an idle connection                      function=Get package=session struct=ConnectionPool
DEBU[2023-10-23 13:08:48.307] Returning a connection                        function=Return package=session struct=ConnectionPool
DEBU[2023-10-23 13:08:48.307] Reuse an idle connection                      function=Get package=session struct=ConnectionPool
DEBU[2023-10-23 13:08:48.307] Returning a connection                        function=Return package=session struct=ConnectionPool
DEBU[2023-10-23 13:08:48.307] scheduled a local file upload /home/user/usersvf_autocreated to /testrug/home/rdms-testers@rug.nl/usersvf_autocreated  function=putOne package=main
DEBU[2023-10-23 13:08:48.307] waiting schedule-wait                         function=Wait package=commons struct=ParallelJobManager
DEBU[2023-10-23 13:08:48.307] waiting job-wait                              function=Wait package=commons struct=ParallelJobManager
DEBU[2023-10-23 13:08:48.307] # threads : 1, max 5                          function=Start package=commons struct=ParallelJobManager
DEBU[2023-10-23 13:08:48.307] Run job 0, /home/user/usersvf_autocreated  function=Start package=commons struct=ParallelJobManager
DEBU[2023-10-23 13:08:48.307] uploading a file /home/user/usersvf_autocreated to /testrug/home/rdms-testers@rug.nl/usersvf_autocreated  function=putOne package=main
DEBU[2023-10-23 13:08:48.307] Reuse an idle connection                      function=Get package=session struct=ConnectionPool
DEBU[2023-10-23 13:08:48.314] Returning a connection                        function=Return package=session struct=ConnectionPool
DEBU[2023-10-23 13:08:48.314] Reuse an idle connection                      function=Get package=session struct=ConnectionPool
DEBU[2023-10-23 13:08:48.322] Returning a connection                        function=Return package=session struct=ConnectionPool
DEBU[2023-10-23 13:08:48.322] upload data object - /home/user/usersvf_autocreated  function=UploadDataObject package=fs
DEBU[2023-10-23 13:08:48.322] Reuse an idle connection                      function=Get package=session struct=ConnectionPool
DEBU[2023-10-23 13:08:50.255] Returning a connection                        function=Return package=session struct=ConnectionPool
DEBU[2023-10-23 13:08:50.255] Run job 0, /home/user/usersvf_autocreated  function=Start package=commons struct=ParallelJobManager
ERRO[2023-10-23 13:08:50.255] failed to upload /home/user/usersvf_autocreated to /testrug/home/rdms-testers@rug.nl/usersvf_autocreated: failed to replicate data object: SYS_NOT_ALLOWED  function=Start package=commons struct=ParallelJobManager
DEBU[2023-10-23 13:08:50.255] # threads : 0, max 5                          function=Start package=commons struct=ParallelJobManager
DEBU[2023-10-23 13:08:50.255] exit job run thread                           function=Start package=commons struct=ParallelJobManager
DEBU[2023-10-23 13:08:50.255] Disconnecting the connection                  function=Disconnect package=connection struct=IRODSConnection
DEBU[2023-10-23 13:08:50.255] Disconnecting the connection                  function=Disconnect package=connection struct=IRODSConnection
ERRO[2023-10-23 13:08:50.256] failed to perform parallel jobs:
    github.com/cyverse/gocommands/cmd/subcmd.processPutCommand
        /github/workspace/cmd/subcmd/put.go:140
  - failed to upload /home/user/usersvf_autocreated to /testrug/home/rdms-testers@rug.nl/usersvf_autocreated:
    github.com/cyverse/gocommands/cmd/subcmd.putOne.func1
        /github/workspace/cmd/subcmd/put.go:215
  - failed to replicate data object:
    github.com/cyverse/go-irodsclient/irods/fs.ReplicateDataObject
        /go/pkg/mod/github.com/cyverse/go-irodsclient@v0.12.16/irods/fs/data_object.go:1290
  - SYS_NOT_ALLOWED  function=main package=main
iRODS Error: SYS_NOT_ALLOWED

Error Trace:
  - failed to perform parallel jobs:
    github.com/cyverse/gocommands/cmd/subcmd.processPutCommand
        /github/workspace/cmd/subcmd/put.go:140
  - failed to upload /home/user/usersvf_autocreated to /testrug/home/rdms-testers@rug.nl/usersvf_autocreated:
    github.com/cyverse/gocommands/cmd/subcmd.putOne.func1
        /github/workspace/cmd/subcmd/put.go:215
  - failed to replicate data object:
    github.com/cyverse/go-irodsclient/irods/fs.ReplicateDataObject
        /go/pkg/mod/github.com/cyverse/go-irodsclient@v0.12.16/irods/fs/data_object.go:1290
  - SYS_NOT_ALLOWED

The files still seem to properly appear on the iRODS side:

$ gocommands/gocmd ls -L  usersvf_autocreated
  rdms-testers@rug.nl   0       rootResc;rootRandy;ptA;replA;randy10;pt100;mnt_irodst100        767     2023-10-23.12:56        &usersvf_autocreated
    sha2:4N5/VDvLflkOMGfsweqy0QVoyLfRmhq0mAWmTRAiNl4=   /mnt/irodst100/home/rdms-testers@rug.nl/usersvf_autocreated
  rdms-testers@rug.nl   1       rootResc;rootRandy;ptA;replA;randy01;pt001;mnt_irodst001        767     2023-10-23.12:56        &usersvf_autocreated
    sha2:4N5/VDvLflkOMGfsweqy0QVoyLfRmhq0mAWmTRAiNl4=   /mnt/irodst001/home/rdms-testers@rug.nl/usersvf_autocreated

Example for folders:

$ gocommands/gocmd put -d  ~/Documents/
DEBU[2023-10-23 13:07:03.012] use sessionID - 2219182                       function=ProcessCommonFlags package=flag
DEBU[2023-10-23 13:07:03.012] reading config file/dir - /home/user/.irods  function=LoadConfigFromFile package=commons
DEBU[2023-10-23 13:07:03.014] reading icommands environment file - /home/user/.irods/irods_environment.json  function=LoadConfigFromFile package=commons
DEBU[2023-10-23 13:07:03.014] reading environment file /home/user/.irods/irods_environment.json  function=Load package=icommands struct=ICommandsEnvironmentManager
DEBU[2023-10-23 13:07:03.015] reading environment password file /home/user/.irods/.irodsA  function=Load package=icommands struct=ICommandsEnvironmentManager
DEBU[2023-10-23 13:07:03.016] Connecting to rdms-test-icat.data.rug.nl:1247  function=Connect package=connection struct=IRODSConnection
DEBU[2023-10-23 13:07:03.020] Start up a connection with CS Negotiation     function=connectWithCSNegotiation package=connection struct=IRODSConnection
DEBU[2023-10-23 13:07:03.223] Start up CS Negotiation                       function=connectWithCSNegotiation package=connection struct=IRODSConnection
DEBU[2023-10-23 13:07:03.223] Client policy - CS_NEG_REQUIRE, server policy - CS_NEG_DONT_CARE  function=connectWithCSNegotiation package=connection struct=IRODSConnection
DEBU[2023-10-23 13:07:03.225] Start up SSL                                  function=sslStartup package=connection struct=IRODSConnection
DEBU[2023-10-23 13:07:03.238] Logging in using native authentication method  function=loginNative package=connection struct=IRODSConnection
DEBU[2023-10-23 13:07:03.290] testing connection                            function=NewIRODSSession package=session
DEBU[2023-10-23 13:07:03.290] Reuse an idle connection                      function=Get package=session struct=ConnectionPool
DEBU[2023-10-23 13:07:03.290] support parallel upload: true                 function=checkConnection package=session
DEBU[2023-10-23 13:07:03.290] Returning a connection                        function=Return package=session struct=ConnectionPool
DEBU[2023-10-23 13:07:03.290] Connecting to rdms-test-icat.data.rug.nl:1247  function=Connect package=connection struct=IRODSConnection
DEBU[2023-10-23 13:07:03.293] Start up a connection with CS Negotiation     function=connectWithCSNegotiation package=connection struct=IRODSConnection
DEBU[2023-10-23 13:07:03.499] Start up CS Negotiation                       function=connectWithCSNegotiation package=connection struct=IRODSConnection
DEBU[2023-10-23 13:07:03.499] Client policy - CS_NEG_REQUIRE, server policy - CS_NEG_DONT_CARE  function=connectWithCSNegotiation package=connection struct=IRODSConnection
DEBU[2023-10-23 13:07:03.500] Start up SSL                                  function=sslStartup package=connection struct=IRODSConnection
DEBU[2023-10-23 13:07:03.514] Logging in using native authentication method  function=loginNative package=connection struct=IRODSConnection
DEBU[2023-10-23 13:07:03.567] testing connection                            function=NewIRODSSession package=session
DEBU[2023-10-23 13:07:03.567] Reuse an idle connection                      function=Get package=session struct=ConnectionPool
DEBU[2023-10-23 13:07:03.567] support parallel upload: true                 function=checkConnection package=session
DEBU[2023-10-23 13:07:03.567] Returning a connection                        function=Return package=session struct=ConnectionPool
DEBU[2023-10-23 13:07:03.567] start job run thread                          function=Start package=commons struct=ParallelJobManager
DEBU[2023-10-23 13:07:03.568] Reuse an idle connection                      function=Get package=session struct=ConnectionPool
DEBU[2023-10-23 13:07:03.577] failed to commit transaction                  error=SYS_NO_API_PRIV function=endTransaction package=session struct=IRODSSession
DEBU[2023-10-23 13:07:03.582] Returning a connection                        function=Return package=session struct=ConnectionPool
DEBU[2023-10-23 13:07:03.582] Disconnecting the connection                  function=Disconnect package=connection struct=IRODSConnection
DEBU[2023-10-23 13:07:03.582] Disconnecting the connection                  function=Disconnect package=connection struct=IRODSConnection
ERRO[2023-10-23 13:07:03.582] failed to make new target path for put /home/user/Documents/ to ./:
    github.com/cyverse/gocommands/cmd/subcmd.processPutCommand
        /github/workspace/cmd/subcmd/put.go:128
  - failed to make dir /testrug/home/rdms-testers@rug.nl/Documents:
    github.com/cyverse/gocommands/cmd/subcmd.makePutTargetDirPath
        /github/workspace/cmd/subcmd/put.go:332
  - mkdir /testrug: permission denied  function=main package=main

Error Trace:
  - failed to make new target path for put /home/user/Documents/ to ./:
    github.com/cyverse/gocommands/cmd/subcmd.processPutCommand
        /github/workspace/cmd/subcmd/put.go:128
  - failed to make dir /testrug/home/rdms-testers@rug.nl/Documents:
    github.com/cyverse/gocommands/cmd/subcmd.makePutTargetDirPath
        /github/workspace/cmd/subcmd/put.go:332
  - mkdir /testrug: permission denied

The main Github page mentions to use the --no_replication flag to troubleshoot this issue. This flag is not available for gocmd put in the current version. I also tried if using other flags like --single_threaded or --no_root change this behavior, but did not see a difference.

Also, if I repeat the exact steps using the previous version (v0.7.11), I do not see any of these error messages. Moreover, I do not get this message when using bput instead of normal put.

iychoi commented 10 months ago

Sorry for the issue. I touched the replication code little while optimizing the code. The new release can fix the issue.

https://github.com/cyverse/gocommands/releases/tag/v0.7.13

jnimoth commented 10 months ago

I just tried the new version v0.7.13 and I still see issues:

# Check that the current version is used
$ ./gocmd --version
{
  "clientVersion": "v0.7.13",
  "gitCommit": "8538cdbbff68e275c36b6586b6642333ddae18b0",
  "buildDate": "2023-10-23T16:13:48Z",
  "goVersion": "go1.18.6",
  "compiler": "gc",
  "platform": "linux/amd64"
}

# Trying to do the transfer via put
$ ./gocmd put --progress  ../example_files/

Error Trace:
  - failed to make new target path for put ../example_files/ to ./:
    github.com/cyverse/gocommands/cmd/subcmd.processPutCommand
        /github/workspace/cmd/subcmd/put.go:128
  - failed to make dir /devrugZone/home/rdms-testers@rug.nl/example_files:
    github.com/cyverse/gocommands/cmd/subcmd.makePutTargetDirPath
        /github/workspace/cmd/subcmd/put.go:332
  - mkdir /devrugZone: permission denied

# Comparison with v0.7.11
$ ./gocmd-0.7.11 put --progress  ../example_files/
/home/user/example_files/example_file_1         ... done! [10.49MB in 79ms]
/home/user/example_files/example_file_3         ... done! [10.49MB in 311ms]
/home/user/example_files/example_file_4         ... done! [10.49MB in 535ms]
/home/user/example_files/example_file_2         ... done! [10.49MB in 810ms]
/home/user/example_files/example_file_10        ... done! [10.49MB in 1.073s]
/home/user/example_files/example_file_5         ... done! [10.49MB in 90ms]
/home/user/example_files/example_file_6         ... done! [10.49MB in 78ms]
/home/user/example_files/example_file_7         ... done! [10.49MB in 82ms]
/home/user/example_files/example_file_8         ... done! [10.49MB in 88ms]
/home/user/example_files/example_file_9         ... done! [10.49MB in 64ms]
iychoi commented 10 months ago

Can you try the new release? I just fixed the bug.

https://github.com/cyverse/gocommands/releases/tag/v0.7.14

jnimoth commented 10 months ago

I still see the same with the new version.

It works fine for files, but as soon as I want to put a folder, I get an error message:

# First check the most current version is indeed used

$ gocommands/gocmd --version
{
  "clientVersion": "v0.7.14",
  "gitCommit": "fcced5101e816034f2433b42c25feef3ed6d9c68",
  "buildDate": "2023-10-24T15:35:58Z",
  "goVersion": "go1.18.6",
  "compiler": "gc",
  "platform": "linux/amd64"
}

# Transfer/put a file works without issue
$ gocommands/gocmd put my_data_archive.tar

# Now the same for a folder
$ ls example_folder/
my_data_archive.tar

$ gocommands/gocmd put -d example_folder/
DEBU[2023-10-25 12:10:55.506] use sessionID - 312934                        function=ProcessCommonFlags package=flag
DEBU[2023-10-25 12:10:55.506] reading config file/dir - /home/user/.irods  function=LoadConfigFromFile package=commons
DEBU[2023-10-25 12:10:55.507] reading icommands environment file - /home/user/.irods/irods_environment.json  function=LoadConfigFromFile package=commons
DEBU[2023-10-25 12:10:55.507] reading environment file /home/user/.irods/irods_environment.json  function=Load package=icommands struct=ICommandsEnvironmentManager
DEBU[2023-10-25 12:10:55.509] reading environment password file /home/user/.irods/.irodsA  function=Load package=icommands struct=ICommandsEnvironmentManager
DEBU[2023-10-25 12:10:55.510] Connecting to rdms-test-icat.data.rug.nl:1247  function=Connect package=connection struct=IRODSConnection
DEBU[2023-10-25 12:10:55.513] Start up a connection with CS Negotiation     function=connectWithCSNegotiation package=connection struct=IRODSConnection
DEBU[2023-10-25 12:10:55.727] Start up CS Negotiation                       function=connectWithCSNegotiation package=connection struct=IRODSConnection
DEBU[2023-10-25 12:10:55.727] Client policy - CS_NEG_REQUIRE, server policy - CS_NEG_DONT_CARE  function=connectWithCSNegotiation package=connection struct=IRODSConnection
DEBU[2023-10-25 12:10:55.729] Start up SSL                                  function=sslStartup package=connection struct=IRODSConnection
DEBU[2023-10-25 12:10:55.744] Logging in using native authentication method  function=loginNative package=connection struct=IRODSConnection
DEBU[2023-10-25 12:10:55.798] testing connection                            function=NewIRODSSession package=session
DEBU[2023-10-25 12:10:55.798] Reuse an idle connection                      function=Get package=session struct=ConnectionPool
DEBU[2023-10-25 12:10:55.798] support parallel upload: true                 function=checkConnection package=session
DEBU[2023-10-25 12:10:55.798] Returning a connection                        function=Return package=session struct=ConnectionPool
DEBU[2023-10-25 12:10:55.798] Connecting to rdms-test-icat.data.rug.nl:1247  function=Connect package=connection struct=IRODSConnection
DEBU[2023-10-25 12:10:55.801] Start up a connection with CS Negotiation     function=connectWithCSNegotiation package=connection struct=IRODSConnection
DEBU[2023-10-25 12:10:56.027] Start up CS Negotiation                       function=connectWithCSNegotiation package=connection struct=IRODSConnection
DEBU[2023-10-25 12:10:56.027] Client policy - CS_NEG_REQUIRE, server policy - CS_NEG_DONT_CARE  function=connectWithCSNegotiation package=connection struct=IRODSConnection
DEBU[2023-10-25 12:10:56.029] Start up SSL                                  function=sslStartup package=connection struct=IRODSConnection
DEBU[2023-10-25 12:10:56.043] Logging in using native authentication method  function=loginNative package=connection struct=IRODSConnection
DEBU[2023-10-25 12:10:56.109] testing connection                            function=NewIRODSSession package=session
DEBU[2023-10-25 12:10:56.109] Reuse an idle connection                      function=Get package=session struct=ConnectionPool
DEBU[2023-10-25 12:10:56.109] support parallel upload: true                 function=checkConnection package=session
DEBU[2023-10-25 12:10:56.109] Returning a connection                        function=Return package=session struct=ConnectionPool
DEBU[2023-10-25 12:10:56.109] Reuse an idle connection                      function=Get package=session struct=ConnectionPool
DEBU[2023-10-25 12:10:56.109] start job run thread                          function=Start package=commons struct=ParallelJobManager
DEBU[2023-10-25 12:10:56.119] failed to commit transaction                  error=SYS_NO_API_PRIV function=endTransaction package=session struct=IRODSSession
DEBU[2023-10-25 12:10:56.124] Returning a connection                        function=Return package=session struct=ConnectionPool
DEBU[2023-10-5 12:10:56.124] Disconnecting the connection                  function=Disconnect package=connection struct=IRODSConnection
DEBU[2023-10-25 12:10:56.125] Disconnecting the connection                  function=Disconnect package=connection struct=IRODSConnection
ERRO[2023-10-25 12:10:56.125] failed to make new target path for put example_folder/ to ./:
    github.com/cyverse/gocommands/cmd/subcmd.processPutCommand
        /github/workspace/cmd/subcmd/put.go:128
  - failed to make dir /testrug/home/rdms-testers@rug.nl/example_folder:
    github.com/cyverse/gocommands/cmd/subcmd.makePutTargetDirPath
        /github/workspace/cmd/subcmd/put.go:332
  - mkdir /testrug: permission denied  function=main package=main

Error Trace:
  - failed to make new target path for put example_folder/ to ./:
    github.com/cyverse/gocommands/cmd/subcmd.processPutCommand
        /github/workspace/cmd/subcmd/put.go:128
  - failed to make dir /testrug/home/rdms-testers@rug.nl/example_folder:
    github.com/cyverse/gocommands/cmd/subcmd.makePutTargetDirPath
        /github/workspace/cmd/subcmd/put.go:332
  - mkdir /testrug: permission denied
iychoi commented 10 months ago

Fixed the bug. Please try the new release v0.7.15. Thanks for testing!

https://github.com/cyverse/gocommands/releases/tag/v0.7.15

jnimoth commented 10 months ago

I can confirm that the changes in v0.7.15 fix the issue for gocmd put (tested on Linux and Win).