Using strace for troubleshoot an UDP port issue


Issue description:

One of my program(A) got binded with an UDP port (20500) which should be assigned to another program(B), here are the steps for trace down where A binded this port:

1. start the process with strace log:
strace -f -s 128 -o proxy.strace ./pxyserverapp_redhat

2. Find out the PID of the process, also check whether the port was taken.
netstat -anp | grep pxy

3. show socket handle list created by this process
cd /proc/28803/fd

4. show process status
cat /proc/28803/status

5. convert port: ntohs(20500) = 5012
cat /proc/net/udp |grep “5014”

6. check the strace log file, and search with keyword 20500:
less proxy.strace

......

28803 close(25 <unfinished ...>
28800 <... select resumed> )            = 1 (out [10])
28803 <... close resumed> )             = 0
28800 nanosleep({0, 10000000},  <unfinished ...>
28803 getsockname(24, {sa_family=AF_INET, sin_port=htons(1720), sin_addr=inet_addr("172.16.72.235")}, [16]) = 028803 getsockname(24, {sa_family=AF_INET, sin_port=htons(1720), sin_addr=inet_addr("172.16.72.235")}, [16]) = 028803 socket(PF_INET, SOCK_DGRAM, IPPROTO_UDP) = 25
28803 ioctl(25, FIONBIO, [1])           = 0
28803 bind(25, {sa_family=AF_INET, sin_port=htons(1819), sin_addr=inet_addr("172.16.72.235")}, 16) = 0
28803 getsockname(25, {sa_family=AF_INET, sin_port=htons(1819), sin_addr=inet_addr("172.16.72.235")}, [16]) = 028803 setsockopt(25, SOL_SOCKET, SO_BROADCAST, [1], 4) = 0
28803 setsockopt(25, SOL_SOCKET, SO_RCVBUF, [81920], 4) = 0
28803 setsockopt(25, SOL_SOCKET, SO_SNDBUF, [81920], 4) = 0
28803 getsockname(25, {sa_family=AF_INET, sin_port=htons(1819), sin_addr=inet_addr("172.16.72.235")}, [16]) = 028803 setsockopt(25, SOL_IP, IP_MULTICAST_TTL, "\24", 1) = 0
28803 setsockopt(25, SOL_IP, IP_MULTICAST_IF, [-347598676], 4) = 0
28803 times(NULL)                       = 450092216
28803 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 26
28803 bind(26, {sa_family=AF_INET, sin_port=htons(20500), sin_addr=inet_addr("0.0.0.0")}, 16) = 0
28803 sched_get_priority_max(SCHED_OTHER) = 0
28803 sched_get_priority_min(SCHED_OTHER) = 0
28803 rt_sigprocmask(SIG_SETMASK, NULL, [RTMIN], 8) = 0
28803 write(6, "\340\373_\276\0\0\0\0\240\363_\2760\252\17\0108L?\t\0\0\0\200\0\0\0\0_\356\26\10\340\361;\t\377\377\377\377\10\363_\276\340\351<\t\20\0\0\0\357\0\0\0\30\363_\276\r\1\0@\340\361;\t\0\0\0\0\340\351<\t\374\30<\t0\0\0\0\20\0\0\0\f\241t\10\0\0\0\0x\25\21\10\320\n\0\0\f\241t\10\0\0\0\0\370\240t\10\374\240t\10\300\240t\10\0\0\0\0"..., 148 <unfinished ...>
28793 <... poll resumed> [{fd=5, events=POLLIN, revents=POLLIN}], 1, 2000) = 1
28796 <... nanosleep resumed> NULL)     = 0
28803 <... write resumed> )             = 148

......

28803 select(26, [24 25], [], NULL, {0, 10000} <unfinished ...>
28796 <... times resumed> NULL)         = 450092222
28796 times(NULL)                       = 450092222
28796 nanosleep({0, 20000000},  <unfinished ...>
28800 <... nanosleep resumed> NULL)     = 0
28800 select(1024, NULL, [10 13], NULL, NULL) = 1 (out [10])
28800 nanosleep({0, 10000000},  <unfinished ...>
28803 <... select resumed> )            = 0 (Timeout)
28803 nanosleep({0, 5000000}, NULL)     = 0
28803 select(26, [24 25], [], NULL, {0, 10000} <unfinished ...>

 

7. Filter the systemcall log list
As you can see, call history list below are relevant:

28803 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 26
28803 bind(26, {sa_family=AF_INET, sin_port=htons(20500), sin_addr=inet_addr(“0.0.0.0”)}, 16) = 0

28803 select(26, [24 25], [], NULL, {0, 10000} <unfinished …>

8. Check your codes
Then check the codes to see whether there are implements like that(Still under investigation).

 

Leave a comment

Your email address will not be published. Required fields are marked *