tracing signal with strace

divyashree · 02-02-2017, 10:32 AM

One of my python programme execute some scripts in a remote system by using ssh with pexpect. That python programme is killed by sighup everytime and I am not able to trace it.

Today I tried to trace it with strace and unable to understand what exactly is sneding SIGHUP to it.

Here is my process entry for the remote ssh:

Code:

oracle   16068 16026  0 09:31 pts/1    00:00:01 /usr/bin/ssh -o ServerAliveInterval=100 -n paasusr@ucf2c-daas-ternspod01-p19mvm1.opcdaas.xxxxx.com cd /u01/data/objectrepoclient/decrypted/output-ternspod01;nohup python pod-bringup.py setup & echo $! > podsetup.pid

And the strace captured output is :

Code:

10:30:42.568407 select(4, [3], [], [], NULL) = 1 (in [3])
10:32:57.463559 read(3, ".com: CHEF_STARTING\r\nucf2c-daas-"..., 2000) = 2000
10:32:57.463671 write(1, ".com: CHEF_STARTING\r\nucf2c-daas-"..., 2000) = 2000
10:32:57.463910 select(0, NULL, NULL, NULL, {0, 100}) = 0 (Timeout)
10:32:57.464262 wait4(16068, 0x7fff2b09fc74, WNOHANG, NULL) = 0
10:32:57.464336 wait4(16068, 0x7fff2b09fc74, WNOHANG, NULL) = 0
10:32:57.464402 select(4, [3], [], [], NULL) = 1 (in [3])
10:32:57.464475 read(3, "\nucf2c-daas-ternspod01-p19main1."..., 2000) = 2000
10:32:57.464549 write(1, "\nucf2c-daas-ternspod01-p19main1."..., 2000) = 2000
10:32:57.464742 select(0, NULL, NULL, NULL, {0, 100}) = 0 (Timeout)
10:32:57.465056 wait4(16068, 0x7fff2b09fc74, WNOHANG, NULL) = 0
10:32:57.465116 wait4(16068, 0x7fff2b09fc74, WNOHANG, NULL) = 0
10:32:57.465176 select(4, [3], [], [], NULL) = 1 (in [3])
10:32:57.465247 read(3, "01-p19main1.opcdaas.oracleintern"..., 2000) = 142
10:32:57.465317 write(1, "01-p19main1.opcdaas.oracleintern"..., 142) = 142
10:32:57.465410 select(0, NULL, NULL, NULL, {0, 100}) = 0 (Timeout)
10:32:57.465731 wait4(16068, 0x7fff2b09fc74, WNOHANG, NULL) = 0
10:32:57.465790 wait4(16068, 0x7fff2b09fc74, WNOHANG, NULL) = 0
10:32:57.465850 select(4, [3], [], [], NULL) = ? ERESTARTNOHAND (To be restarted)
10:38:14.907547 --- SIGHUP (Hangup) @ 0 (0) ---
10:38:14.907674 select(4, [3], [], [], NULL) = 1 (in [3])
10:41:34.984200 read(3, "om: CHEF_STARTING\r\nucf2c-daas-te"..., 2000) = 2000
10:41:34.984343 write(1, "om: CHEF_STARTING\r\nucf2c-daas-te"..., 2000) = -1 EPIPE (Broken pipe)
10:41:34.984426 --- SIGPIPE (Broken pipe) @ 0 (0) ---
10:41:34.984622 close(3)                = 0
10:41:34.984747 select(0, NULL, NULL, NULL, {0, 100000}) = 0 (Timeout)
10:41:35.085003 wait4(16068, 0x7fff2b09fff4, WNOHANG, NULL) = 0
10:41:35.085076 wait4(16068, 0x7fff2b09fff4, WNOHANG, NULL) = 0
10:41:35.085144 wait4(16068, 0x7fff2b09fdd4, WNOHANG, NULL) = 0
10:41:35.085213 wait4(16068, 0x7fff2b09fdd4, WNOHANG, NULL) = 0
10:41:35.085300 wait4(16068, 0x7fff2b09fc64, WNOHANG, NULL) = 0
10:41:35.085379 wait4(16068, 0x7fff2b09fc64, WNOHANG, NULL) = 0
10:41:35.085458 kill(16068, SIGHUP)     = 0
10:41:35.085640 select(0, NULL, NULL, NULL, {0, 100000}) = 0 (Timeout)
10:41:35.185879 wait4(16068, 0x7fff2b09fdd4, WNOHANG, NULL) = 0
10:41:35.185950 wait4(16068, 0x7fff2b09fdd4, WNOHANG, NULL) = 0
10:41:35.186026 wait4(16068, 0x7fff2b09fc64, WNOHANG, NULL) = 0
10:41:35.186087 wait4(16068, 0x7fff2b09fc64, WNOHANG, NULL) = 0
10:41:35.186146 kill(16068, SIGCONT)    = 0
10:41:35.186224 select(0, NULL, NULL, NULL, {0, 100000}) = 0 (Timeout)
10:41:35.286472 wait4(16068, 0x7fff2b09fdd4, WNOHANG, NULL) = 0
10:41:35.286545 wait4(16068, 0x7fff2b09fdd4, WNOHANG, NULL) = 0
10:41:35.286626 wait4(16068, 0x7fff2b09fc64, WNOHANG, NULL) = 0
10:41:35.286686 wait4(16068, 0x7fff2b09fc64, WNOHANG, NULL) = 0
10:41:35.286749 kill(16068, SIGINT)     = 0
10:41:35.286829 select(0, NULL, NULL, NULL, {0, 100000}) = ? ERESTARTNOHAND (To be restarted)
10:41:35.288909 --- SIGCHLD (Child exited) @ 0 (0) ---
10:41:35.288944 select(0, NULL, NULL, NULL, {0, 97991}) = 0 (Timeout)
10:41:35.387181 wait4(16068, [{WIFEXITED(s) && WEXITSTATUS(s) == 255}], WNOHANG, NULL) = 16068
10:41:35.387386 pipe([3, 4])            = 0
10:41:35.387491 fcntl(4, F_GETFD)       = 0
10:41:35.387582 fcntl(4, F_SETFD, FD_CLOEXEC) = 0
10:41:35.387664 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fba483459d0) = 17636
10:41:35.389289 close(4)                = 0
10:41:35.389426 mmap(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fba409e5000
10:41:35.389524 read(3, "", 1048576)    = 0
10:41:35.390148 mremap(0x7fba409e5000, 1052672, 4096, MREMAP_MAYMOVE) = 0x7fba409e5000
10:41:35.390221 close(3)                = 0
10:41:35.390294 munmap(0x7fba409e5000, 4096) = 0
10:41:35.390413 wait4(17636, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 17636
10:41:35.408230 --- SIGCHLD (Child exited) @ 0 (0) ---

I am not able to understand this trace logs. can anyone please help me understanding this ?

pan64 · 02-02-2017, 11:04 AM

you can catch sighup in python and print whatever you want (for example the process sent that signal)
https://docs.python.org/2/library/signal.html