Stuck commands

[dave14305]

Has anyone else observed any "stuck" commands on their router since upgrading to 386.x? Below is a frequent occurrence of the wl command getting stuck being spawned by conn_diag (this process was created at 4:10 AM). But I've also seen it happen with some nvram get commands (I once had Skynet stuck for hours reading nvram after a firewall-start). I haven't factory reset in a while, and I'm not likely to. It's not much of an issue, only an annoyance. I can kill the stuck process and it will eventually return later.

 

[dave14305]

Still seeing this behavior despite a few upgrades and factory resets since April. No one else?

 

[RMerlin]

Never seen that on any of the routers I work on. Try manually running the command to see what happens.

conn_diag is closed source, so it's impossible to look at it.

 

[dave14305]

I can run the wl command manually just fine over and over, even when the older process is still stuck, and it returns the negative noise value. It's very odd. Most times when I try to determine the time of the hung process, it's in the middle of the night. Will keep an eye on it.

 

[Maverickcdn]

I had the same wl command running on my unit as well, forgot to check its start time before killing it.

 

[dave14305]

From another thread.

Spoiler: Normal nvram strace

# strace -r nvram get wan0_enable
     0.000000 execve("/bin/nvram", ["nvram", "get", "wan0_enable"], 0x7ff58279a8 /* 18 vars */ <unfinished ...>
     0.000618 [ Process PID=1356 runs in 32 bit mode. ]
strace: WARNING: Proper structure decoding for this personality is not supported, please consider building strace with mpers support enabled.
     0.000041 <... execve resumed>)     = 0
     0.000064 brk(NULL)                 = 0x76d000
     0.000056 uname({sysname="Linux", nodename="router", ...}) = 0
     0.000093 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf7649000
     0.000059 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
     0.000128 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
     0.000068 fstat64(3, 0xffae1600)    = 0
     0.000050 mmap2(NULL, 10528, PROT_READ, MAP_PRIVATE, 3, 0) = 0xf7646000
     0.000041 close(3)                  = 0
     0.000051 open("/lib/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
     0.000048 read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0xm\1\0004\0\0\0"..., 512) = 512
     0.000051 fstat64(3, 0xffae1640)    = 0
     0.000041 mmap2(NULL, 1299824, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf74dd000
     0.000047 mprotect(0xf7605000, 65536, PROT_NONE) = 0
     0.000055 mmap2(0xf7615000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x128000) = 0xf7615000
     0.000062 mmap2(0xf7618000, 9584, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xf7618000
     0.000060 close(3)                  = 0
     0.000055 open("/lib/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = 3
     0.000049 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\254\317\0\0004\0\0\0"..., 512) = 512
     0.000048 fstat64(3, 0xffae1628)    = 0
     0.000038 mmap2(NULL, 182372, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf74b0000
     0.000044 mprotect(0xf74cd000, 61440, PROT_NONE) = 0
     0.000047 mmap2(0xf74dc000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1c000) = 0xf74dc000
     0.000060 close(3)                  = 0
     0.000049 open("/lib/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
     0.000047 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0(\t\0\0004\0\0\0"..., 512) = 512
     0.000047 fstat64(3, 0xffae1610)    = 0
     0.000038 mmap2(NULL, 73912, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf749d000
     0.000044 mprotect(0xf749f000, 61440, PROT_NONE) = 0
     0.000047 mmap2(0xf74ae000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1000) = 0xf74ae000
     0.000069 close(3)                  = 0
     0.000043 open("/lib/libnvram.so", O_RDONLY|O_CLOEXEC) = 3
     0.000047 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\08\t\0\0004\0\0\0"..., 512) = 512
     0.000047 fstat64(3, 0xffae15f8)    = 0
     0.000037 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf7645000
     0.000046 mmap2(NULL, 69528, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf748c000
     0.000045 mprotect(0xf748d000, 61440, PROT_NONE) = 0
     0.000046 mmap2(0xf749c000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0) = 0xf749c000
     0.000056 close(3)                  = 0
     0.000042 open("/usr/lib/libshared.so", O_RDONLY|O_CLOEXEC) = 3
     0.000049 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\214X\1\0004\0\0\0"..., 512) = 512
     0.000046 fstat64(3, 0xffae15e0)    = 0
     0.000038 mmap2(NULL, 646528, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf73ee000
     0.000044 mprotect(0xf745b000, 65536, PROT_NONE) = 0
     0.000045 mmap2(0xf746b000, 45056, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6d000) = 0xf746b000
     0.000060 mmap2(0xf7476000, 89472, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xf7476000
     0.000061 close(3)                  = 0
     0.000051 open("/lib/libwlcsm.so", O_RDONLY|O_CLOEXEC) = 3
     0.000049 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\200\34\0\0004\0\0\0"..., 512) = 512
     0.000047 fstat64(3, 0xffae15c8)    = 0
     0.000038 mmap2(NULL, 90092, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf73d8000
     0.000045 mprotect(0xf73dd000, 61440, PROT_NONE) = 0
     0.000047 mmap2(0xf73ec000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x4000) = 0xf73ec000
     0.000068 close(3)                  = 0
     0.000053 open("/lib/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
     0.000049 read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\\I\0\0004\0\0\0"..., 512) = 512
     0.000048 fstat64(3, 0xffae1400)    = 0
     0.000038 mmap2(NULL, 164436, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf73af000
     0.000044 mprotect(0xf73c4000, 65536, PROT_NONE) = 0
     0.000054 mmap2(0xf73d4000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x15000) = 0xf73d4000
     0.000061 mmap2(0xf73d6000, 4692, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xf73d6000
     0.000056 close(3)                  = 0
     0.000075 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf7644000
     0.000052 set_tls(0xf7644780)       = 0
     0.000194 mprotect(0xf7615000, 8192, PROT_READ) = 0
     0.000087 mprotect(0xf73d4000, 4096, PROT_READ) = 0
     0.000377 mprotect(0xf74ae000, 4096, PROT_READ) = 0
     0.000091 mprotect(0xf764a000, 4096, PROT_READ) = 0
     0.000050 munmap(0xf7646000, 10528) = 0
     0.000052 set_tid_address(0xf7644328) = 1356
     0.000035 set_robust_list(0xf7644330, 12) = 0
     0.000049 rt_sigaction(SIGRTMIN, {sa_handler=0xf73b3278, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0xf7509b10}, NULL, 8) = 0
     0.000063 rt_sigaction(SIGRT_1, {sa_handler=0xf73b335c, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0xf7509b10}, NULL, 8) = 0
     0.000063 rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
     0.000057 ugetrlimit(RLIMIT_STACK, {rlim_cur=2048*1024, rlim_max=RLIM_INFINITY}) = 0
     0.000180 mmap2(NULL, 135168, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf738e000
     0.000086 stat64("/jffs", 0xffae1950) = 0
     0.000057 stat64("/jffs/nvram_war", 0xffae1950) = 0
     0.000093 socket(AF_NETLINK, SOCK_RAW, 0x1f /* NETLINK_??? */) = 3
     0.000076 bind(3, {sa_family=AF_NETLINK, nl_pid=1356, nl_groups=00000000}, 12) = 0
     0.000065 brk(NULL)                 = 0x76d000
     0.000035 brk(0x78e000)             = 0x78e000
     0.000050 open("/proc/sys/kernel/pid_max", O_RDONLY) = 4
     0.000070 fstat64(4, 0xffae1858)    = 0
     0.000037 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf7648000
     0.000042 read(4, "32768\n", 1024)  = 6
     0.000085 close(4)                  = 0
     0.000040 munmap(0xf7648000, 4096)  = 0
     0.000047 socket(AF_NETLINK, SOCK_RAW, 0x1f /* NETLINK_??? */) = 4
     0.000044 bind(4, {sa_family=AF_NETLINK, nl_pid=34126, nl_groups=00000000}, 12) = 0
     0.000052 sendmsg(3, {msg_name=0xcffae19e0, msg_namelen=-5367336, msg_iov=NULL, msg_iovlen=0, msg_control=0xf73ecd74ffae2e04, msg_controllen=4148091588, msg_flags=MSG_DONTROUTE|MSG_CTRUNC|MSG_TRUNC|MSG_WAITALL|MSG_SYN|MSG_CONFIRM|MSG_RST|MSG_SENDPAGE_NOTLAST|MSG_BATCH|MSG_NO_SHARED_FRAGS|MSG_ZEROCOPY|MSG_FASTOPEN|MSG_CMSG_CLOEXEC|MSG_CMSG_COMPAT|0x1ba00000}, 0) = 36
     0.000138 recvmsg(3, {msg_name=0xcffae19e0, msg_namelen=-5367336, msg_iov=NULL, msg_iovlen=0, msg_control=0xffae2e0400000000, msg_controllen=17815917715420794228, msg_flags=0}, 0) = 48
     0.000272 fstat64(1, 0xffae1980)    = 0
     0.000040 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf7648000
     0.000047 write(1, "1\n", 21
)        = 2
     0.000046 munmap(0xf738e000, 135168) = 0
     0.000073 exit_group(0)             = ?
     0.000224 +++ exited with 0 +++

 

[dave14305]

Spoiler: Hung nvram strace

Every 0s: strace -r nvram get wan0_enable                                                                  2022-06-14 19:15:30

     0.000000 execve("/bin/nvram", ["nvram", "get", "wan0_enable"], 0x7fea378f88 /* 18 vars */ <unfinished ...>
     0.000698 [ Process PID=1098 runs in 32 bit mode. ]
strace: WARNING: Proper structure decoding for this personality is not supported, please consider building strace with mpers support enabled.
     0.000039 <... execve resumed>)     = 0
     0.000091 brk(NULL)                 = 0x42e000
     0.000057 uname({sysname="Linux", nodename="router", ...}) = 0
     0.000094 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf7124000
     0.000055 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
     0.000134 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
     0.000069 fstat64(3, 0xffb8e450)    = 0
     0.000057 mmap2(NULL, 10528, PROT_READ, MAP_PRIVATE, 3, 0) = 0xf7121000
     0.000042 close(3)                  = 0
     0.000051 open("/lib/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
     0.000062 read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0xm\1\0004\0\0\0"..., 512) = 512
     0.000052 fstat64(3, 0xffb8e490)    = 0
     0.000041 mmap2(NULL, 1299824, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf6fb8000
     0.000046 mprotect(0xf70e0000, 65536, PROT_NONE) = 0
     0.000196 mmap2(0xf70f0000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x128000) = 0xf70f0000
     0.000063 mmap2(0xf70f3000, 9584, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xf70f3000
     0.000059 close(3)                  = 0
     0.000056 open("/lib/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = 3
     0.000048 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\254\317\0\0004\0\0\0"..., 512) = 512
     0.000047 fstat64(3, 0xffb8e478)    = 0
     0.000038 mmap2(NULL, 182372, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf6f8b000
     0.000044 mprotect(0xf6fa8000, 61440, PROT_NONE) = 0
     0.000072 mmap2(0xf6fb7000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1c000) = 0xf6fb7000
     0.000060 close(3)                  = 0
     0.000048 open("/lib/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
     0.000046 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0(\t\0\0004\0\0\0"..., 512) = 512
     0.000047 fstat64(3, 0xffb8e460)    = 0
     0.000038 mmap2(NULL, 73912, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf6f78000
     0.000044 mprotect(0xf6f7a000, 61440, PROT_NONE) = 0
     0.000046 mmap2(0xf6f89000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1000) = 0xf6f89000
     0.000125 close(3)                  = 0
     0.000044 open("/lib/libnvram.so", O_RDONLY|O_CLOEXEC) = 3
     0.000047 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\08\t\0\0004\0\0\0"..., 512) = 512
     0.000046 fstat64(3, 0xffb8e448)    = 0
     0.000037 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf7120000
     0.000072 mmap2(NULL, 69528, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf6f67000
     0.000046 mprotect(0xf6f68000, 61440, PROT_NONE) = 0
     0.000048 mmap2(0xf6f77000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0) = 0xf6f77000
     0.000057 close(3)                  = 0
     0.000044 open("/usr/lib/libshared.so", O_RDONLY|O_CLOEXEC) = 3
     0.000050 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\214X\1\0004\0\0\0"..., 512) = 512
     0.000074 fstat64(3, 0xffb8e430)    = 0
     0.000038 mmap2(NULL, 646528, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf6ec9000
     0.000044 mprotect(0xf6f36000, 65536, PROT_NONE) = 0
     0.000047 mmap2(0xf6f46000, 45056, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6d000) = 0xf6f46000
     0.000060 mmap2(0xf6f51000, 89472, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xf6f51000
     0.000081 close(3)                  = 0
     0.000050 open("/lib/libwlcsm.so", O_RDONLY|O_CLOEXEC) = 3
     0.000048 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\200\34\0\0004\0\0\0"..., 512) = 512
     0.000088 fstat64(3, 0xffb8e418)    = 0
     0.000138 mmap2(NULL, 90092, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf6eb3000
     0.000049 mprotect(0xf6eb8000, 61440, PROT_NONE) = 0
     0.000046 mmap2(0xf6ec7000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x4000) = 0xf6ec7000
     0.000067 close(3)                  = 0
     0.000056 open("/lib/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
     0.000048 read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\\I\0\0004\0\0\0"..., 512) = 512
     0.000047 fstat64(3, 0xffb8e250)    = 0
     0.000038 mmap2(NULL, 164436, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf6e8a000
     0.000045 mprotect(0xf6e9f000, 65536, PROT_NONE) = 0
     0.000050 mmap2(0xf6eaf000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x15000) = 0xf6eaf000
     0.000076 mmap2(0xf6eb1000, 4692, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xf6eb1000
     0.000058 close(3)                  = 0
     0.000071 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf711f000
     0.000051 set_tls(0xf711f780)       = 0
     0.000260 mprotect(0xf70f0000, 8192, PROT_READ) = 0
     0.000090 mprotect(0xf6eaf000, 4096, PROT_READ) = 0
     0.000369 mprotect(0xf6f89000, 4096, PROT_READ) = 0
     0.000164 mprotect(0xf7125000, 4096, PROT_READ) = 0
     0.000052 munmap(0xf7121000, 10528) = 0
     0.000054 set_tid_address(0xf711f328) = 1098
     0.000036 set_robust_list(0xf711f330, 12) = 0
     0.000061 rt_sigaction(SIGRTMIN, {sa_handler=0xf6e8e278, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0xf6fe4b10}, NULL, 8) = 0
     0.000064 rt_sigaction(SIGRT_1, {sa_handler=0xf6e8e35c, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0xf6fe4b10}, NULL, 8) = 0
     0.000063 rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
     0.000055 ugetrlimit(RLIMIT_STACK, {rlim_cur=2048*1024, rlim_max=RLIM_INFINITY}) = 0
     0.000210 mmap2(NULL, 135168, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf6e69000
     0.000084 stat64("/jffs", 0xffb8e7a0) = 0
     0.000055 stat64("/jffs/nvram_war", 0xffb8e7a0) = 0
     0.000117 socket(AF_NETLINK, SOCK_RAW, 0x1f /* NETLINK_??? */) = 3
     0.000078 bind(3, {sa_family=AF_NETLINK, nl_pid=1098, nl_groups=00000000}, 12) = -1 EADDRINUSE (Address already in use)
     0.000073 brk(NULL)                 = 0x42e000
     0.000049 brk(0x44f000)             = 0x44f000
     0.000052 sendmsg(3, {msg_name=0xcffb8e830, msg_namelen=-4659160, msg_iov=NULL, msg_iovlen=0, msg_control=0xf6ec7d74ffb8ee04, msg_controllen=4142697156, msg_flags=MSG_DONTROUTE|MSG_CTRUNC|MSG_PROBE|MSG_TRUNC|MSG_DONTWAIT|MSG_WAITALL|MSG_FIN|MSG_CONFIRM|MSG_ERRQUEUE|MSG_NOSIGNAL|MSG_MORE|MSG_NO_SHARED_FRAGS|MSG_ZEROCOPY|MSG_FASTOPEN|MSG_CMSG_CLOEXEC|MSG_CMSG_COMPAT|0x1bb00000}, 0) = 36
     0.000178 recvmsg(3,

 

[dave14305]

Spoiler: Hung wl strace

Every 0s: strace -r wl -i eth5 noise                                                                       2022-06-14 20:07:33

     0.000000 execve("/usr/sbin/wl", ["wl", "-i", "eth5", "noise"], 0x7fe50f5f30 /* 18 vars */ <unfinished ...>
     0.000662 [ Process PID=1163 runs in 32 bit mode. ]
strace: WARNING: Proper structure decoding for this personality is not supported, please consider building strace with mpers support enabled.
     0.000040 <... execve resumed>)     = 0
     0.000066 brk(NULL)                 = 0x82f000
     0.000057 uname({sysname="Linux", nodename="router", ...}) = 0
     0.000096 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf72fa000
     0.000064 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
     0.000127 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
     0.000068 fstat64(3, 0xffd6d570)    = 0
     0.000319 mmap2(NULL, 10528, PROT_READ, MAP_PRIVATE, 3, 0) = 0xf72f7000
     0.000044 close(3)                  = 0
     0.000053 open("/lib/libnvram.so", O_RDONLY|O_CLOEXEC) = 3
     0.000050 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\08\t\0\0004\0\0\0"..., 512) = 512
     0.000051 fstat64(3, 0xffd6d5b0)    = 0
     0.000041 mmap2(NULL, 69528, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf72bb000
     0.000047 mprotect(0xf72bc000, 61440, PROT_NONE) = 0
     0.000049 mmap2(0xf72cb000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0) = 0xf72cb000
     0.000058 close(3)                  = 0
     0.000045 open("/lib/libwlcsm.so", O_RDONLY|O_CLOEXEC) = 3
     0.000048 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\200\34\0\0004\0\0\0"..., 512) = 512
     0.000047 fstat64(3, 0xffd6d598)    = 0
     0.000038 mmap2(NULL, 90092, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf72a5000
     0.000044 mprotect(0xf72aa000, 61440, PROT_NONE) = 0
     0.000046 mmap2(0xf72b9000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x4000) = 0xf72b9000
     0.000067 close(3)                  = 0
     0.000046 open("/usr/lib/libshared.so", O_RDONLY|O_CLOEXEC) = 3
     0.000050 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\214X\1\0004\0\0\0"..., 512) = 512
     0.000048 fstat64(3, 0xffd6d580)    = 0
     0.000038 mmap2(NULL, 646528, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf7207000
     0.000044 mprotect(0xf7274000, 65536, PROT_NONE) = 0
     0.000047 mmap2(0xf7284000, 45056, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6d000) = 0xf7284000
     0.000059 mmap2(0xf728f000, 89472, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xf728f000
     0.000060 close(3)                  = 0
     0.000054 open("/lib/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
     0.000047 read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0xm\1\0004\0\0\0"..., 512) = 512
     0.000048 fstat64(3, 0xffd6d568)    = 0
     0.000038 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf72f6000
     0.000047 mmap2(NULL, 1299824, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf70c9000
     0.000045 mprotect(0xf71f1000, 65536, PROT_NONE) = 0
     0.000052 mmap2(0xf7201000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x128000) = 0xf7201000
     0.000059 mmap2(0xf7204000, 9584, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xf7204000
     0.000056 close(3)                  = 0
     0.000061 open("/lib/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
     0.000050 read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\\I\0\0004\0\0\0"..., 512) = 512
     0.000048 fstat64(3, 0xffd6d460)    = 0
     0.000038 mmap2(NULL, 164436, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf70a0000
     0.000045 mprotect(0xf70b5000, 65536, PROT_NONE) = 0
     0.000050 mmap2(0xf70c5000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x15000) = 0xf70c5000
     0.000060 mmap2(0xf70c7000, 4692, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xf70c7000
     0.000055 close(3)                  = 0
     0.000073 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf72f5000
     0.000048 set_tls(0xf72f54c0)       = 0
     0.000257 mprotect(0xf7201000, 8192, PROT_READ) = 0
     0.000088 mprotect(0xf70c5000, 4096, PROT_READ) = 0
     0.000298 mprotect(0xf72fb000, 4096, PROT_READ) = 0
     0.000051 munmap(0xf72f7000, 10528) = 0
     0.000050 set_tid_address(0xf72f5068) = 1163
     0.000036 set_robust_list(0xf72f5070, 12) = 0
     0.000052 rt_sigaction(SIGRTMIN, {sa_handler=0xf70a4278, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0xf70f5b10}, NULL, 8) = 0
     0.000063 rt_sigaction(SIGRT_1, {sa_handler=0xf70a435c, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0xf70f5b10}, NULL, 8) = 0
     0.000064 rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
     0.000059 ugetrlimit(RLIMIT_STACK, {rlim_cur=2048*1024, rlim_max=RLIM_INFINITY}) = 0
     0.000215 socket(AF_INET, SOCK_DGRAM, IPPROTO_IP) = 3
     0.000077 ioctl(3, SIOCDEVPRIVATE, 0xffd6db00) = 0
     0.000257 close(3)                  = 0
     0.000055 socket(AF_INET, SOCK_DGRAM, IPPROTO_IP) = 3
     0.000041 ioctl(3, SIOCDEVPRIVATE, 0xffd6db00) = 0
     0.000149 close(3)                  = 0
     0.000069 stat64("/jffs", 0xffd6d9a8) = 0
     0.000055 stat64("/jffs/nvram_war", 0xffd6d9a8) = 0
     0.000086 socket(AF_NETLINK, SOCK_RAW, 0x1f /* NETLINK_??? */) = 3
     0.000055 bind(3, {sa_family=AF_NETLINK, nl_pid=1163, nl_groups=00000000}, 12) = -1 EADDRINUSE (Address already in use)
     0.000137 brk(NULL)                 = 0x82f000
     0.000038 brk(0x850000)             = 0x850000
     0.000056 sendmsg(3, {msg_name=0xcffd6da38, msg_namelen=-2696656, msg_iov=NULL, msg_iovlen=0, msg_control=0xf72b9d7400090dd4, msg_controllen=3505436194745028, msg_flags=MSG_WAITALL|MSG_FIN|MSG_CONFIRM|MSG_RST|MSG_NOSIGNAL|MSG_MORE|MSG_SENDPAGE_NOTLAST|MSG_BATCH|MSG_ZEROCOPY|MSG_FASTOPEN|MSG_CMSG_CLOEXEC|MSG_CMSG_COMPAT|0x1bd00000}, 0) = 36
     0.000148 recvmsg(3,

 

[Oracle]

We are in the process of testing a rough patch (band aid) for this defect.
This seems to affect (all?) owners of the RT-AC86U.

 

[ColinTaylor]

@dave14305 From the straces I can't see that the nvram and wl commands are doing anything particularly wrong. So I'm assuming some "other" process has grabbed the netlink nl_pid. On my router the list of netlink sockets that are held open is fairly static.

Can you try this. Issue this command just before running the script and copy the output somewhere (e.g. notepad).

cat /proc/net/netlink | sort -nk 3

Then run an strace script that causes the problem to occur:

#!/bin/sh
while true
do
   strace nvram get wan0_enable
done

Assuming this script crashes, check the nl_pid associated with the EADDRINUSE error. Is this pid in the list that you created earlier (column 3)?

 

[dave14305]

Assuming this script crashes, check the nl_pid associated with the EADDRINUSE error. Is this pid in the list that you created earlier (column 3)?

Yes, it is. 20735 in this latest test. So there is inadequate testing for nl_pid uniqueness by nvram.

The existing inode is from eapd, based on lsof output.

rtradmin@router:/tmp/home/root# cat /proc/net/netlink
sk       Eth Pid    Groups   Rmem     Wmem     Dump     Locks     Drops     Inode
ffffffc010654800 31  20735  00000000 0        0        0 2        0        19802500

     0.000091 socket(AF_NETLINK, SOCK_RAW, 0x1f /* NETLINK_??? */) = 3<socket:[22348842]>
     0.000089 bind(3<socket:[22348842]>, {sa_family=AF_NETLINK, nl_pid=20735, nl_groups=00000000}, 12) = -1 EADDRINUSE (Address already in use)
     0.000087 brk(NULL)                 = 0x7d8000
     0.000282 brk(0x7f9000)             = 0x7f9000
     0.000058 sendmsg(3<socket:[22348842]>, {msg_name=0xcff803c30, msg_namelen=-8373208, msg_iov=NULL, msg_iovlen=0, msg_control=0xf72c2d74ff804e06, msg_controllen=4146870980, msg_flags=MSG_DONTROUTE|MSG_CTRUNC|MSG_PROBE|MSG_TRUNC|MSG_DONTWAIT|MSG_WAITALL|MSG_FIN|MSG_SYN|MSG_CONFIRM|MSG_RST|MSG_ERRQUEUE|MSG_ZEROCOPY|MSG_FASTOPEN|MSG_CMSG_CLOEXEC|MSG_CMSG_COMPAT|0x1b800000}, 0) = 36
     0.000162 recvmsg(3<socket:[22348842]>,
        
rtradmin@router:/tmp/home/root# lsof | grep 19802500
eapd      20746                 rtradmin    6u  netlink                         0t0 19802500 unknown protocol: 31

 

[ColinTaylor]

Yes, it is. 20735 in this latest test.

Good. That's progress.

So there is inadequate testing for nl_pid uniqueness by nvram.

From my reading of the man page I would say it ought to be safe using your own pid on the first netlink statement. But that's more by convention rather than being mandatory. All the other processes I looked at followed this convention. So on balance I would say the "blame" lies mostly with another process not following the convention.

The existing inode is from eapd, based on lsof output.

Can you kill that process and run the test again?

 

[dave14305]

Can you kill that process and run the test again?

Not at the moment, but I also find a hung wl process with pid 20741 and there is already an existing netlink entry for nl_pid 20741 belonging to mcpd (with pid 21376). I wasn’t stracing wl at all, so I’m not 100% sure what nl_pid it was trying.

 

[ColinTaylor]

Not at the moment, but I also find a hung wl process with pid 20741 and there is already an existing netlink entry for nl_pid 20741 belonging to mcpd (with pid 21376). I wasn’t stracing wl at all, so I’m not 100% sure what nl_pid it was trying.

I don't see any anomalies on my RT-AX86u (as expected):

# echo $(pidof eapd); lsof | grep eapd | grep netlink
1231
eapd       1231                 admin    3u  netlink                         0t0       2131 unknown protocol: 31
eapd       1231                 admin    4u  netlink                         0t0       2132 unknown protocol: 31
eapd       1231                 admin    6u  netlink                         0t0       3411 unknown protocol: 31
eapd       1231                 admin    7u  netlink                         0t0       3412 unknown protocol: 31
# echo $(pidof mcpd); lsof | grep mcpd | grep netlink
2596
mcpd       2596                 admin    3u  netlink                         0t0       2131 unknown protocol: 31
mcpd       2596                 admin    4u  netlink                         0t0       2132 unknown protocol: 31
mcpd       2596                 admin    6u  netlink                         0t0       3935 unknown protocol: 31
mcpd       2596                 admin    7u  netlink                         0t0       3936 unknown protocol: 31
mcpd       2596                 admin   11u  netlink                         0t0       4054 unknown protocol: 30

 

[dave14305]

I don't see any anomalies on my RT-AX86u (as expected):

# echo $(pidof eapd); lsof | grep eapd | grep netlink
1231
eapd       1231                 admin    3u  netlink                         0t0       2131 unknown protocol: 31
eapd       1231                 admin    4u  netlink                         0t0       2132 unknown protocol: 31
eapd       1231                 admin    6u  netlink                         0t0       3411 unknown protocol: 31
eapd       1231                 admin    7u  netlink                         0t0       3412 unknown protocol: 31
# echo $(pidof mcpd); lsof | grep mcpd | grep netlink
2596
mcpd       2596                 admin    3u  netlink                         0t0       2131 unknown protocol: 31
mcpd       2596                 admin    4u  netlink                         0t0       2132 unknown protocol: 31
mcpd       2596                 admin    6u  netlink                         0t0       3935 unknown protocol: 31
mcpd       2596                 admin    7u  netlink                         0t0       3936 unknown protocol: 31
mcpd       2596                 admin   11u  netlink                         0t0       4054 unknown protocol: 30

So do you think it’s just random luck that a pre-existing process selects a random nl_pid that happens to later match the pid of a new process? Do your straces show the pid being used first, followed by a random pid greater than /proc/sys/kernel/pid_max?

 

[ColinTaylor]

So do you think it’s just random luck that a pre-existing process selects a random nl_pid that happens to later match the pid of a new process?

That's my current theory - perhaps random or a perhaps a programming error. But I'm having a hard time trying to think of ways to prove that as I don't own an RT-AC86U. Normally I'd just keep poking around at things hoping to spot something that doesn't look right.

Do your straces show the pid being used first, followed by a random pid greater than /proc/sys/kernel/pid_max?

AFAICT they're not random - but again, my router doesn't suffer from this problem. From all the netlink output I've seen (not just from nvram and wl) the first nl_pid is the same as the pid and the second nl_pid (if there is one) is pid+32770 (pid_max+2?). This behaviour for netlink protocol 31 is consistent on my router. I'm wondering whether it's the same for you.

 

[dave14305]

AFAICT they're not random - but again, my router doesn't suffer from this problem. From all the netlink output I've seen (not just from nvram and wl) the first nl_pid is the same as the pid and the second nl_pid (if there is one) is pid+32770 (pid_max+2?). This behaviour for netlink protocol 31 is consistent on my router. I'm wondering whether it's the same for you.

Good eye.

rtradmin@router:/tmp/home/root# lsof -p $(pidof eapd) | grep netlink
eapd    24095 rtradmin    3u  netlink               0t0      146 unknown protocol: 31
eapd    24095 rtradmin    4u  netlink               0t0      147 unknown protocol: 31
eapd    24095 rtradmin    6u  netlink               0t0 22394445 unknown protocol: 31
eapd    24095 rtradmin    7u  netlink               0t0 22394446 unknown protocol: 31
rtradmin@router:/tmp/home/root# grep -E " 146 | 147 |22394445$|22394446$" /proc/net/netlink | sort -nk3
ffffffc017057400 31  1      00000000 0        0        0 2        0        146    
ffffffc015768000 31  24084  00000000 0        0        0 2        0        22394445
ffffffc017057000 31  32771  00000000 0        0        0 2        0        147    
ffffffc01204a400 31  56854  00000000 0        0        0 2        0        22394446

But eapd using 24084 is suspiciously rude.

 

[ColinTaylor]

But eapd using 24084 is suspiciously rude.

I don't think there's a direct relationship between the node and the nl_pid. They look like different things to me. (I have 68 different processes using node 2131)

# lsof | grep eapd | grep netlink
eapd       1231                 admin    3u  netlink                         0t0       2131 unknown protocol: 31
eapd       1231                 admin    4u  netlink                         0t0       2132 unknown protocol: 31
eapd       1231                 admin    6u  netlink                         0t0       3411 unknown protocol: 31
eapd       1231                 admin    7u  netlink                         0t0       3412 unknown protocol: 31

# grep -E " 2131 | 2132 | 3411 | 3412 " /proc/net/netlink | sort -nk3
ffffffc0324e4000 31  1      00000000 0        0        0 2        0        2131
ffffffc02d926400 31  1216   00000000 0        0        0 2        0        3411
ffffffc03dd9cc00 31  32771  00000000 0        0        0 2        0        2132
ffffffc02d926000 31  33986  00000000 0        0        0 2        0        3412

P.S. I've stopped using -p with lsof because it won't show any associated threads (not that I've seen any).

 

[dave14305]

I don't think there's a direct relationship between the node and the nl_pid. They look like different things to me. (I have 68 different processes using node 2131)

I’m just saying that I don’t understand why eapd with pid 24095 uses nl_pid 24084 and then 24084+32770. Unless the precompiled binaries are broken in that regard.

 

[SomeWhereOverTheRainBow]

I’m just saying that I don’t understand why eapd with pid 24095 uses nl_pid 24084 and then 24084+32770. Unless the precompiled binaries are broken in that regard.

Has anyone phoned home to Asus with these findings? Sounds like something is broken upstream in their mess of closed source-ness. Maybe @RMerlin would be able to point them in the direction of what needs to be looked at?