REST API: 401 Unauthorized: permission denied - invalid PVE ticket

J

jan.svoboda

Member
Jun 11, 2020
32
1
13
Hello,

I have some problems with authentication ticket. I know that there are multiple threads about the same issue. I tried to follow steps from those threads that worked for someone but nothing worked for me.
I use the REST API very extensively so it is crucial to have it working. I use proxmoxer 1.1.0 Python 3 library with HTTPS backend as a wrapper to the REST API.

I get HTTP 401 Unauthorized: permission denied - invalid PVE ticket while running a Python script using REST API very often and before the ticket's 2 hours lifetime. Sometimes it doesn't obtain the ticket at all.
It happens a few times a week. I searched for some clues in logs but I have never found the reason why this happens.

All nodes are NTP synchronized, I use the default systemd-timesyncd.

I would be very thankful if someone looks to attached logs and advise me what should I reconfigure or which other clues I should search for.

I have 5 Proxmox nodes in one cluster, all of them running the same version Proxmox VE 6.1-8.
root@devel1:~# pveversion -v
pve-manager: 6.1-8 (running version: 6.1-8/806edfe1)
pve-kernel-helper: 6.1-7
pve-kernel-5.3: 6.1-6
pve-kernel-5.3.18-3-pve: 5.3.18-3
pve-kernel-5.3.18-2-pve: 5.3.18-2
pve-kernel-5.3.10-1-pve: 5.3.10-1
ceph-fuse: 12.2.11+dfsg1-2.1+b1
corosync: 3.0.3-pve1
criu: 3.11-3
glusterfs-client: 7.4-1
ifupdown: residual config
ifupdown2: 2.0.1-1+pve8
ksm-control-daemon: 1.3-1
libjs-extjs: 6.0.1-10
libknet1: 1.15-pve1
libpve-access-control: 6.0-6
libpve-apiclient-perl: 3.0-3
libpve-common-perl: 6.0-17
libpve-guest-common-perl: 3.0-5
libpve-http-server-perl: 3.0-5
libpve-storage-perl: 6.1-5
libqb0: 1.0.5-1
libspice-server1: 0.14.2-4~pve6+1
lvm2: 2.03.02-pve4
lxc-pve: 3.2.1-1
lxcfs: 4.0.1-pve1
novnc-pve: 1.1.0-1
openvswitch-switch: 2.12.0-1
proxmox-mini-journalreader: 1.1-1
proxmox-widget-toolkit: 2.1-3
pve-cluster: 6.1-4
pve-container: 3.0-23
pve-docs: 6.1-6
pve-edk2-firmware: 2.20200229-1
pve-firewall: 4.0-10
pve-firmware: 3.0-6
pve-ha-manager: 3.0-9
pve-i18n: 2.0-4
pve-qemu-kvm: 4.1.1-4
pve-xtermjs: 4.3.0-1
qemu-server: 6.1-7
smartmontools: 7.1-pve2
spiceterm: 3.1-1
vncterm: 1.6-1
zfsutils-linux: 0.8.3-pve1

root@devel1:~# timedatectl
Local time: Wed 2020-06-17 10:43:41 CEST
Universal time: Wed 2020-06-17 08:43:41 UTC
RTC time: Wed 2020-06-17 08:43:41
Time zone: Europe/Prague (CEST, +0200)
System clock synchronized: yes
NTP service: active
RTC in local TZ: no

root@devel1:~# systemctl status -l systemd-timesyncd
● systemd-timesyncd.service - Network Time Synchronization
Loaded: loaded (/lib/systemd/system/systemd-timesyncd.service; enabled; vendor preset: enabled)
Drop-In: /usr/lib/systemd/system/systemd-timesyncd.service.d
└─disable-with-time-daemon.conf
Active: active (running) since Mon 2020-06-15 15:25:07 CEST; 1 day 19h ago
Docs: man:systemd-timesyncd.service(8)
Main PID: 4020 (systemd-timesyn)
Status: "Synchronized to time server for the first time 89.221.212.46:123 (0.debian.pool.ntp.org)."
Tasks: 2 (limit: 7372)
Memory: 6.5M
CGroup: /system.slice/systemd-timesyncd.service
└─4020 /lib/systemd/systemd-timesyncd

Jun 15 15:25:06 devel1 systemd[1]: Starting Network Time Synchronization...
Jun 15 15:25:07 devel1 systemd[1]: Started Network Time Synchronization.
Jun 15 15:25:07 devel1 systemd-timesyncd[4020]: Synchronized to time server for the first time 89.221.210.188:123 (0.debian.pool.ntp.org).
Jun 15 15:44:31 devel1 systemd-timesyncd[4020]: Timed out waiting for reply from 89.221.210.188:123 (0.debian.pool.ntp.org).
Jun 15 15:44:31 devel1 systemd-timesyncd[4020]: Synchronized to time server for the first time 89.221.212.46:123 (0.debian.pool.ntp.org).

root@devel1:~# systemctl status -l corosync
● corosync.service - Corosync Cluster Engine
Loaded: loaded (/lib/systemd/system/corosync.service; enabled; vendor preset: enabled)
Active: active (running) since Mon 2020-06-15 15:46:01 CEST; 1 day 18h ago
Docs: man:corosync
man:corosync.conf
man:corosync_overview
Main PID: 8412 (corosync)
Tasks: 9 (limit: 7372)
Memory: 147.6M
CGroup: /system.slice/corosync.service
└─8412 /usr/sbin/corosync -f

Jun 15 15:46:24 devel1 corosync[8412]: [KNET ] rx: host: 4 link: 0 is up
Jun 15 15:46:24 devel1 corosync[8412]: [KNET ] host: host: 4 (passive) best link: 0 (pri: 1)
Jun 15 15:46:25 devel1 corosync[8412]: [TOTEM ] A new membership (1.1860e) was formed. Members joined: 4
Jun 15 15:46:25 devel1 corosync[8412]: [CPG ] downlist left_list: 0 received
Jun 15 15:46:25 devel1 corosync[8412]: [CPG ] downlist left_list: 0 received
Jun 15 15:46:25 devel1 corosync[8412]: [CPG ] downlist left_list: 0 received
Jun 15 15:46:25 devel1 corosync[8412]: [CPG ] downlist left_list: 0 received
Jun 15 15:46:25 devel1 corosync[8412]: [CPG ] downlist left_list: 0 received
Jun 15 15:46:25 devel1 corosync[8412]: [QUORUM] Members[5]: 1 2 3 4 5
Jun 15 15:46:25 devel1 corosync[8412]: [MAIN ] Completed service synchronization, ready to provide service.

root@devel1:~# systemctl status -l pveproxy
● pveproxy.service - PVE API Proxy Server
Loaded: loaded (/lib/systemd/system/pveproxy.service; enabled; vendor preset: enabled)
Active: active (running) since Tue 2020-06-16 15:51:44 CEST; 18h ago
Process: 16677 ExecStartPre=/usr/bin/pvecm updatecerts --silent (code=exited, status=0/SUCCESS)
Process: 16686 ExecStart=/usr/bin/pveproxy start (code=exited, status=0/SUCCESS)
Process: 18296 ExecReload=/usr/bin/pveproxy restart (code=exited, status=0/SUCCESS)
Main PID: 16688 (pveproxy)
Tasks: 5 (limit: 7372)
Memory: 288.8M
CGroup: /system.slice/pveproxy.service
├─ 1561 pveproxy worker
├─ 1812 pveproxy worker
├─ 2197 pveproxy worker
├─16688 pveproxy
└─36856 pveproxy worker (shutdown)

Jun 17 10:38:49 devel1 pveproxy[16688]: starting 1 worker(s)
Jun 17 10:38:49 devel1 pveproxy[16688]: worker 1812 started
Jun 17 10:38:49 devel1 pveproxy[1812]: Clearing outdated entries from certificate cache
Jun 17 10:39:31 devel1 pveproxy[48057]: worker exit
Jun 17 10:40:48 devel1 pveproxy[16688]: worker 1386 finished
Jun 17 10:40:48 devel1 pveproxy[16688]: starting 1 worker(s)
Jun 17 10:40:48 devel1 pveproxy[16688]: worker 2197 started
Jun 17 10:40:49 devel1 pveproxy[2196]: got inotify poll request in wrong process - disabling inotify
Jun 17 10:40:49 devel1 pveproxy[2197]: Clearing outdated entries from certificate cache
Jun 17 10:40:50 devel1 pveproxy[2196]: worker exit

192.168.7.10 - - [17/Jun/2020:09:47:29 +0200] "POST /api2/json/access/ticket HTTP/1.1" 401 13 "-" "python-requests/2.23.0"
192.168.7.10 - - [17/Jun/2020:09:55:20 +0200] "POST /api2/json/access/ticket HTTP/1.1" 401 13 "-" "python-requests/2.23.0"
192.168.7.10 - - [17/Jun/2020:10:23:43 +0200] "POST /api2/json/access/ticket HTTP/1.1" 401 13 "-" "python-requests/2.23.0"
192.168.7.10 - - [17/Jun/2020:10:37:45 +0200] "GET /api2/json/nodes HTTP/1.1" 401 5 "-" "python-requests/2.23.0"
192.168.7.10 - - [17/Jun/2020:10:37:56 +0200] "GET /api2/json/nodes/devel2/qemu/241/status/current HTTP/1.1" 401 5 "-" "python-requests/2.23.0"
192.168.7.10 - - [17/Jun/2020:10:39:15 +0200] "GET /api2/json/nodes HTTP/1.1" 401 5 "-" "python-requests/2.23.0"

root@devel1:~# systemctl status -l pvedaemon
● pvedaemon.service - PVE API Daemon
Loaded: loaded (/lib/systemd/system/pvedaemon.service; enabled; vendor preset: enabled)
Active: active (running) since Tue 2020-06-16 15:51:50 CEST; 18h ago
Process: 16725 ExecStart=/usr/bin/pvedaemon start (code=exited, status=0/SUCCESS)
Main PID: 16728 (pvedaemon)
Tasks: 6 (limit: 7372)
Memory: 298.7M
CGroup: /system.slice/pvedaemon.service
├─ 827 pvedaemon worker
├─16728 pvedaemon
├─36835 task UPID:devel1:00008FE3:1265C8BA:5EE9C7CB:vncproxy:261:zima@ldap:
├─36837 /usr/bin/perl /usr/sbin/qm vncproxy 261
├─47263 pvedaemon worker
└─48069 pvedaemon worker

Jun 17 10:40:56 devel1 pvedaemon[47263]: <root@pam> successful auth for user 'icinga@pve'
Jun 17 10:41:01 devel1 pvedaemon[47263]: <root@pam> successful auth for user 'icinga@pve'
Jun 17 10:41:04 devel1 pvedaemon[48069]: <root@pam> successful auth for user 'icinga@pve'
Jun 17 10:41:04 devel1 pvedaemon[827]: <root@pam> successful auth for user 'icinga@pve'
Jun 17 10:41:14 devel1 pvedaemon[827]: <root@pam> successful auth for user 'icinga@pve'
Jun 17 10:41:22 devel1 pvedaemon[47263]: <root@pam> successful auth for user 'icinga@pve'
Jun 17 10:41:39 devel1 pvedaemon[48069]: <root@pam> successful auth for user '<censored>@ldap'
Jun 17 10:41:50 devel1 pvedaemon[827]: <root@pam> successful auth for user '<censored>@ldap'
Jun 17 10:41:50 devel1 pvedaemon[48069]: <root@pam> successful auth for user 'icinga@pve'
Jun 17 10:41:52 devel1 pvedaemon[47263]: <root@pam> successful auth for user 'icinga@pve'

Thank you and have a nice day.
 
I found some interesting log from pveproxy after restarting it, though I don't know what that means: Jun 17 10:49:48 devel1 pveproxy[3861]: Can't call method "push_write" on an undefined value at /usr/share/perl5/PVE/APIServer/AnyEvent.pm line 255.
root@devel1:~# systemctl status -l pveproxy
● pveproxy.service - PVE API Proxy Server
Loaded: loaded (/lib/systemd/system/pveproxy.service; enabled; vendor preset: enabled)
Active: active (running) since Wed 2020-06-17 10:49:05 CEST; 2min 38s ago
Process: 3851 ExecStartPre=/usr/bin/pvecm updatecerts --silent (code=exited, status=0/SUCCESS)
Process: 3855 ExecStart=/usr/bin/pveproxy start (code=exited, status=0/SUCCESS)
Main PID: 3859 (pveproxy)
Tasks: 4 (limit: 7372)
Memory: 241.2M
CGroup: /system.slice/pveproxy.service
├─3859 pveproxy
├─3860 pveproxy worker
├─3862 pveproxy worker
└─4079 pveproxy worker

Jun 17 10:49:05 devel1 pveproxy[3859]: starting 3 worker(s)
Jun 17 10:49:05 devel1 pveproxy[3859]: worker 3860 started
Jun 17 10:49:05 devel1 pveproxy[3859]: worker 3861 started
Jun 17 10:49:05 devel1 pveproxy[3859]: worker 3862 started
Jun 17 10:49:05 devel1 systemd[1]: Started PVE API Proxy Server.
Jun 17 10:49:48 devel1 pveproxy[3861]: Can't call method "push_write" on an undefined value at /usr/share/perl5/PVE/APIServer/AnyEvent.pm line 255.
Jun 17 10:49:53 devel1 pveproxy[3861]: worker exit
Jun 17 10:49:53 devel1 pveproxy[3859]: worker 3861 finished
Jun 17 10:49:53 devel1 pveproxy[3859]: starting 1 worker(s)
Jun 17 10:49:53 devel1 pveproxy[3859]: worker 4079 started
 
you can try running pvedaemon and pveproxy in foreground/debug mode and correlate the output with your failed attempts to use the API.
 
You must log in or register to reply here.
Top Bottom