HEAD /: 400 Bad Request

[fsoy]

Hi there,
on a PBS server I notice this errors in /var/log/syslog :
proxmox-backup-proxy[2536]: HEAD /: 400 Bad Request: [client [::ffff:127.0.0.1]:53468] request failed

This is caused by something locally (client [::ffff:127.0.0.1]), but I don't know what. And it occurs every 5 minutes between, strangely, only the first half of each hour. I found no crontab that can be guilty.
There is no other errors, and backups (at night) seems good.
Any idea about that ? Thanks.

 

[oguz]

hi,

This is caused by something locally (client [::ffff:127.0.0.1]), but I don't know what. And it occurs every 5 minutes between, strangely, only the first half of each hour. I found no crontab that can be guilty.

do you have some kind of monitoring agent running on the server?

you can check your running processes with ps auxfw command. ss -antop should show you connections being made from your machine (and the processes making them). maybe these help you finding the culprit for those requests.

 

[fsoy]

Good tips to try, thanks. The process 2536 is proxmox-backup-proxy, listening on port 8007. There is a proxmox-backup-api listening on port 82.
So I tried this command :
while true; do ss -antop | grep -v LISTEN > /tmp/ss.log; tail -1 /var/log/syslog | grep HEAD; if [ $? -eq 0 ]; then break; fi; sleep 1; done
so I have the result of 'ss' at the time the error was logged. But unfortunatly, I see nothing revelant, only some connections from outside to ports 22 and 111, a lot of "timer" in TIME-WAIT on port 82, but nothing on 8007.
I continue to search...

 

[oguz]

so I have the result of 'ss' at the time the error was logged. But unfortunatly, I see nothing revelant, only some connections from outside to ports 22 and 111, a lot of "timer" in TIME-WAIT on port 82, but nothing on 8007.
I continue to search...

you can also check with lsof -i command, something like lsof -i :8007 should give you inbound/outbound connections for that port

 

[fsoy]

Hi,
I change my command by :
while true; do lsof -i :8007 > /tmp/400.log; ss -antop | grep -v LISTEN | grep -v TIME-WAIT >> /tmp/400.log; tail -1 /var/log/syslog | grep HEAD; if [ $? -eq 0 ]; then break; fi; done
removing "sleep 1" to be sure to have the last results. But found nothing :/

COMMAND    PID   USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
proxmox-b 2536 backup   16u  IPv6  18381      0t0  TCP *:8007 (LISTEN)
proxmox-b 2536 backup   17u  IPv6  18381      0t0  TCP *:8007 (LISTEN)
State       Recv-Q   Send-Q      Local Address:Port         Peer Address:Port                                                                                 
ESTAB       0        68         xxx.yyy.75.155:22           112.85.42.13:52918   users:(("sshd",pid=19280,fd=3),("sshd",pid=19279,fd=3)) timer:(on,15sec,6)   
ESTAB       0        0          xxx.yyy.75.155:111         xxx.yyy.68.26:37394   users:(("rpcbind",pid=1993,fd=12))                                           
ESTAB       0        0          xxx.yyy.75.155:111         185.204.1.216:65449   users:(("rpcbind",pid=1993,fd=19))                                           
ESTAB       0        0          xxx.yyy.75.155:111       172.104.140.107:46644   users:(("rpcbind",pid=1993,fd=10))                                           
FIN-WAIT-1  0        69         xxx.yyy.75.155:22          46.101.207.32:44346   timer:(on,1min34sec,9)                                                       
ESTAB       0        0          xxx.yyy.75.155:111        178.79.148.229:46618   users:(("rpcbind",pid=1993,fd=17))                                           
ESTAB       0        0          xxx.yyy.75.155:111       172.104.140.107:44906   users:(("rpcbind",pid=1993,fd=16))                                           
ESTAB       0        0          xxx.yyy.75.155:111        172.104.159.48:41548   users:(("rpcbind",pid=1993,fd=11))                                           
FIN-WAIT-1  0        69         xxx.yyy.75.155:22         104.236.124.45:58607   timer:(on,17sec,8)                                                           
ESTAB       0        0          xxx.yyy.75.155:111         88.80.186.144:45926   users:(("rpcbind",pid=1993,fd=27))                                           
ESTAB       0        0          xxx.yyy.75.155:111         88.80.186.144:44380   users:(("rpcbind",pid=1993,fd=23))                                           
ESTAB       0        0          xxx.yyy.75.155:111        104.140.188.34:49355   users:(("rpcbind",pid=1993,fd=24))                                           
ESTAB       0        0          xxx.yyy.75.155:22           37.58.163.97:36715   users:(("sshd",pid=15448,fd=3)) timer:(keepalive,117min,0)                   
ESTAB       0        0          xxx.yyy.75.155:111        170.130.187.14:53541   users:(("rpcbind",pid=1993,fd=15))                                           
ESTAB       0        0          xxx.yyy.75.155:22           37.58.163.97:25529   users:(("sshd",pid=9202,fd=3)) timer:(keepalive,112min,0)                   
ESTAB       0        0          xxx.yyy.75.155:111         92.118.161.45:60561   users:(("rpcbind",pid=1993,fd=21))                                           
ESTAB       0        0          xxx.yyy.75.155:111        178.79.148.229:59888   users:(("rpcbind",pid=1993,fd=14))                                           
ESTAB       0        0          xxx.yyy.75.155:111        212.83.132.206:36629   users:(("rpcbind",pid=1993,fd=28))                                           
ESTAB       0        0          xxx.yyy.75.155:111         170.130.187.6:59248   users:(("rpcbind",pid=1993,fd=20))                                           
ESTAB       0        0          xxx.yyy.75.155:111         xxx.yyy.68.26:35610   users:(("rpcbind",pid=1993,fd=13))                                           
ESTAB       0        0          xxx.yyy.75.155:111         88.80.186.144:59560   users:(("rpcbind",pid=1993,fd=25))                                           
ESTAB       0        0          xxx.yyy.75.155:111         92.118.160.13:52795   users:(("rpcbind",pid=1993,fd=22))                                           
ESTAB       0        0          xxx.yyy.75.155:111          45.79.178.89:27210   users:(("rpcbind",pid=1993,fd=26))                                           
ESTAB       0        0          xxx.yyy.75.155:111        15.228.124.206:39528   users:(("rpcbind",pid=1993,fd=18))

but maybe it's just a process too furtive to be logged...

 

[oguz]

hi,

with your command: while true; do lsof -i :8007 > /tmp/400.log; ss -antop | grep -v LISTEN | grep -v TIME-WAIT >> /tmp/400.log; tail -1 /var/log/syslog | grep HEAD; if [ $? -eq 0 ]; then break; fi; done
you overwrite the log file at each run because of the single > at the beginning.

try like the following:

watch -n1 -c '(ss -antop && lsof -i) | grep 8007 | tee -a /tmp/8007.log'

run it for long enough, then just do a grep 8007 /tmp/8007.log | sort -u to filter the results

 

[fsoy]

Hi,
I tried this, for a time where at least 10 error messages was loggued in syslog. Unfortunatly, nothing appears in 8007.log. You noticed that the error messages contains the process id ("client [::ffff:127.0.0.1]:53468"), never the same, and these IDs never appear in 8007.log
The strange thing is that occurs exactly every 5 minutes. There is no monitoring locally (except Zabbix with a local agent but it don't check pbs or port 8007, only cpu and mem and ZFS).
I don't think that this is the case, but do you think that the "Restart=on-failure" in the systemd service can be guilty (but 5 minutes it seems too large for a service check) ?