executeSSHCommand reports GetListValue(): result is 500 (INTERNAL_ERROR)
-
I use executeSSHCommand in my script and it sometimes doesn't return value. I've set DebugLevel = 9 and there is following message in the agent log:
2020.04.09 13:12:51.493 *D* [comm.cs.1 ] GetListValue(): result is 500 (INTERNAL_ERROR)The behavior is very strange. The problem occurs only on Raspberry Pi or on x64 linux accesed from other server and even in this case it doesn't occur every time.
I wrote a C program to test it. It has two parameters first is sleep time in seconds a the second one is the return value (output to stdout).The log is attached.
-
It could be due to timeout. Server will wait for answer from agent for time specified in server configuration parameter AgentCommandTimeout. If you are accessing remote system over slow link or command execution takes significant amount of time then executeSSHCommand may just timeout.
Best regards,
Victor -
I don't think it is due to timeout. I've tested it with AgentCommandTimeout = 30000.
I've started a test script calling my test program manually and it always returned after specified waiting time. I the log I sent I only used the waiting time 0s and 1s, but I've tested it with longer waiting times too 10s and 20s and event in this case the script returned after 10s and 20s.
-
In your log the error usually happens 1s after the connection is created, but there is one place, where it happens just few ms afterwards:
2020.04.09 13:34:04.722 *D* [ ] SSH: created new session [email protected]:22/1 2020.04.09 13:34:05.828 *D* [comm.cs.1 ] GetListValue(): result is 500 (INTERNAL_ERROR) -- 2020.04.09 13:34:12.345 *D* [ ] SSH: acquired existing session [email protected]:22/1 2020.04.09 13:34:13.366 *D* [comm.cs.1 ] GetListValue(): result is 500 (INTERNAL_ERROR) -- 2020.04.09 13:34:19.436 *D* [ ] SSH: acquired existing session [email protected]:22/1 2020.04.09 13:34:19.456 *D* [comm.cs.1 ] GetListValue(): result is 500 (INTERNAL_ERROR) -- 2020.04.09 13:34:30.496 *D* [ ] SSH: acquired existing session [email protected]:22/1 2020.04.09 13:34:31.517 *D* [comm.cs.1 ] GetListValue(): result is 500 (INTERNAL_ERROR)Do you see anything that would correspond to these events in /var/log/auth.log on the Raspberry?
Can you take a tcpdump to see, if the connection is established at all when this happens? -
The time the error occurs depends on waiting time in seconds in my test program (first parameter of the program). In one test I've used the value 0, therefore the program ended immediately in other tests I've used the waiting time 1s.
2020.04.09 13:34:04.416 *D* [comm.cs.1 ] Requesting list "SSH.Command(192.168.18.134,"pi","raspberry","/opt/disp_ctrl/mon_c 1 5")" 2020.04.09 13:34:04.722 *D* [ ] SSH: created new session [email protected]:22/1 2020.04.09 13:34:05.828 *D* [comm.cs.1 ] GetListValue(): result is 500 (INTERNAL_ERROR) -- 2020.04.09 13:34:12.345 *D* [comm.cs.1 ] Requesting list "SSH.Command(192.168.18.134,"pi","raspberry","/opt/disp_ctrl/mon_c 1 5")" 2020.04.09 13:34:12.345 *D* [ ] SSH: acquired existing session [email protected]:22/1 2020.04.09 13:34:13.366 *D* [comm.cs.1 ] GetListValue(): result is 500 (INTERNAL_ERROR) -- 2020.04.09 13:34:19.436 *D* [comm.cs.1 ] Requesting list "SSH.Command(192.168.18.134,"pi","raspberry","/opt/disp_ctrl/mon_c 0 5")" 2020.04.09 13:34:19.436 *D* [ ] SSH: acquired existing session [email protected]:22/1 2020.04.09 13:34:19.456 *D* [comm.cs.1 ] GetListValue(): result is 500 (INTERNAL_ERROR) -- 2020.04.09 13:34:30.496 *D* [comm.cs.1 ] Requesting list "SSH.Command(192.168.18.134,"pi","raspberry","/opt/disp_ctrl/mon_c 1 5")" 2020.04.09 13:34:30.496 *D* [ ] SSH: acquired existing session [email protected]:22/1 2020.04.09 13:34:31.517 *D* [comm.cs.1 ] GetListValue(): result is 500 (INTERNAL_ERROR)I will take the tcpdump tomorrow and I will try to use more different waiting times.
-
I did a new test with different waiting times (0, 1, 2, 5, 10, 0 and 1s) only the last try was successful and the call has returned the value 5.
I've attached the captured ssh communication which was done localy only (from agent on the same RPi) therefore the network cannot be the source of the problem.
I've attached the source of my test program, but it is very simple.
Here is the filtered agent log (the full log is attached):2020.04.15 09:03:24.435 *D* [comm.cs.1 ] Requesting list "SSH.Command(192.168.18.134,"pi","raspberry","/opt/disp_ctrl/mon_c 0 5")" 2020.04.15 09:03:24.736 *D* [ ] SSH: created new session [email protected]:22/1 2020.04.15 09:03:24.841 *D* [comm.cs.1 ] GetListValue(): result is 500 (INTERNAL_ERROR) -- 2020.04.15 09:03:34.496 *D* [comm.cs.1 ] Requesting list "SSH.Command(192.168.18.134,"pi","raspberry","/opt/disp_ctrl/mon_c 1 5")" 2020.04.15 09:03:34.496 *D* [ ] SSH: acquired existing session [email protected]:22/1 2020.04.15 09:03:35.517 *D* [comm.cs.1 ] GetListValue(): result is 500 (INTERNAL_ERROR) -- 2020.04.15 09:03:42.637 *D* [comm.cs.1 ] Requesting list "SSH.Command(192.168.18.134,"pi","raspberry","/opt/disp_ctrl/mon_c 2 5")" 2020.04.15 09:03:42.637 *D* [ ] SSH: acquired existing session [email protected]:22/1 2020.04.15 09:03:44.657 *D* [comm.cs.1 ] GetListValue(): result is 500 (INTERNAL_ERROR) -- 2020.04.15 09:03:52.416 *D* [comm.cs.1 ] Requesting list "SSH.Command(192.168.18.134,"pi","raspberry","/opt/disp_ctrl/mon_c 5 5")" 2020.04.15 09:03:52.416 *D* [ ] SSH: acquired existing session [email protected]:22/1 2020.04.15 09:03:57.436 *D* [comm.cs.1 ] GetListValue(): result is 500 (INTERNAL_ERROR) -- 2020.04.15 09:04:03.635 *D* [comm.cs.1 ] Requesting list "SSH.Command(192.168.18.134,"pi","raspberry","/opt/disp_ctrl/mon_c 10 5")" 2020.04.15 09:04:03.635 *D* [ ] SSH: acquired existing session [email protected]:22/1 2020.04.15 09:04:03.917 *D* [comm.cs.1 ] Received message CMD_KEEPALIVE (146) 2020.04.15 09:04:13.656 *D* [comm.cs.1 ] GetListValue(): result is 500 (INTERNAL_ERROR) -- 2020.04.15 09:04:20.165 *D* [comm.cs.1 ] Requesting list "SSH.Command(192.168.18.134,"pi","raspberry","/opt/disp_ctrl/mon_c 0 5")" 2020.04.15 09:04:20.165 *D* [ ] SSH: acquired existing session [email protected]:22/1 2020.04.15 09:04:20.185 *D* [comm.cs.1 ] GetListValue(): result is 500 (INTERNAL_ERROR) -- 2020.04.15 09:04:29.965 *D* [comm.cs.1 ] Requesting list "SSH.Command(192.168.18.134,"pi","raspberry","/opt/disp_ctrl/mon_c 1 5")" 2020.04.15 09:04:29.966 *D* [ ] SSH: acquired existing session [email protected]:22/1 2020.04.15 09:04:30.986 *D* [comm.cs.1 ] GetListValue(): result is 0 (SUCCESS)
Hello! It looks like you're interested in this conversation, but you don't have an account yet.
Getting fed up of having to scroll through the same posts each visit? When you register for an account, you'll always come back to exactly where you were before, and choose to be notified of new replies (either via email, or push notification). You'll also be able to save bookmarks and upvote posts to show your appreciation to other community members.
With your input, this post could be even better 💗
Register Login