Loss of access to bacularis menus with a 504 error
224 views
Skip to first unread message
Romain Delmas
Jun 18, 2024, 5:28:48 AM6/18/24
to bacularis
Hello Marcin,
Few days ago i was obliged to operate a changeover between my two web servers (bacularis) and, more generally, of my bacula infrastructure.
So, i've changed master/secondary articulation in my different configurations :
- DRBD (replication datas) ;
- REPMGR (cluster postgresql).
To improve the swicthing, i have disabled our failover system (pacemaker, corosync).
At the same time, an incorrect operation purged all my bacularis files on my second node ; and, as the packages database has been updated, i was obliged to install the bacularis 3.2.1 package.
Once the switch has been made for the background services, i used the webserver configuration wizard to join the database/catalog (test ok), to get bconsole settings (test ok), to test all configuration files and binaries (tests ok) and add an oath2 login (webaccess ok).
Since, i've got several problems :
- Dashboard does not appear in the IHFM ;
- Slow as soon as i try to access menus ;
- Many "504 Gateway Time Out"
- Clearly, I can't access Jobs, clients or storage menu of Bacularis.
But, i can use the API without any troubles (well, just tested the web part, as the reconfiguration or adding user) ; i can access the configuration menu on the website (with slow progress and sometines a 504 error).
Do you have any idea about the whys and wherefores ?
For all intents and purposes, backups are always operational via the bconsle console on my second node. So, i can manage the necessary with this interface, but...
I join to you some screens about permissions, errors messages...
Thank you in advance for your attention to this message,
And hope that all is well with you,
Sincerely
Romain
Few days ago i was obliged to operate a changeover between my two web servers (bacularis) and, more generally, of my bacula infrastructure.
So, i've changed master/secondary articulation in my different configurations :
- DRBD (replication datas) ;
- REPMGR (cluster postgresql).
To improve the swicthing, i have disabled our failover system (pacemaker, corosync).
At the same time, an incorrect operation purged all my bacularis files on my second node ; and, as the packages database has been updated, i was obliged to install the bacularis 3.2.1 package.
Once the switch has been made for the background services, i used the webserver configuration wizard to join the database/catalog (test ok), to get bconsole settings (test ok), to test all configuration files and binaries (tests ok) and add an oath2 login (webaccess ok).
Since, i've got several problems :
- Dashboard does not appear in the IHFM ;
- Slow as soon as i try to access menus ;
- Many "504 Gateway Time Out"
- Clearly, I can't access Jobs, clients or storage menu of Bacularis.
But, i can use the API without any troubles (well, just tested the web part, as the reconfiguration or adding user) ; i can access the configuration menu on the website (with slow progress and sometines a 504 error).
Do you have any idea about the whys and wherefores ?
For all intents and purposes, backups are always operational via the bconsle console on my second node. So, i can manage the necessary with this interface, but...
I join to you some screens about permissions, errors messages...
Thank you in advance for your attention to this message,
And hope that all is well with you,
Sincerely
Romain
Marcin Haba
Jun 18, 2024, 10:12:34 PM6/18/24
to Romain Delmas, bacularis
Hello Romain
Thanks for your feedback and for describing us all the problem. Indeed, something has to be wrong there. At least it should not time out.
First, I would propose to adjust a little permissions. If your webserver/PHP works with user and group www-data:www-data then your current setting with user bacula in www-data group can not work in some cases. I would propose to do the opposite, assign the www-data user to the bacula group and tune ownership a bit.
# remove bacula user from www-data
gpasswd --delete www-data bacula
# add www-data user to bacula group
usermod -a -G bacula www-data
# set permissions for bacula files
chown root:bacula /etc/bacula/bacula-{dir,sd,fd}.conf /etc/bacula/bconsole.conf
# restart PHP-FPM (example for version 7.4):
systemctl restart php7.4-fpm
Once we have the permissions ready, next thing what could be checked is - what causes this timeout. The easiest way of checking is is to load the page that loads slowly and quickly at the same time see the system process list on the host with Bacularis. Just simple "ps auxfwww" is sufficient. This way we will see what causes that the process times out.
From my perspective it can be bconsole process but you will see. I know, you showed that in the command line this bconsole works well, thanks for this test, however using bconsole from the command line and using it in a web application can be a bit different in results, not because of permissions but because of other things.
Once we know the process that takes most of the time until timeout, we will know what to do. Also I would propose to consider adding to the web server log information about how much time every request takes. Information about how to do it you can find in this mail thread on this group:
https://groups.google.com/g/bacularis/c/x0NLsBD24IM
So, the access log will look like here:
127.0.0.1 - - [18/Jun/2024:09:11:46 +0200] "GET /api/v3/jobs/?limit=15000&director=darkstar-dir HTTP/1.1" 200 202822 "-" "-" 1148ms
127.0.0.1 - - [18/Jun/2024:09:11:47 +0200] "GET /api/v3/joblog/messages?director=darkstar-dir HTTP/1.1" 200 66 "-" "-" 247ms
and we see that the first request to get jobs took 1.1 seconds, and second to get joblog messages took 0.2 second. It helps to find which request is the slowest and causes time out.
For now that is all. Good luck with checking the above. Please let us know about the results.
Best regards,
Marcin Haba (gani)
Thanks for your feedback and for describing us all the problem. Indeed, something has to be wrong there. At least it should not time out.
First, I would propose to adjust a little permissions. If your webserver/PHP works with user and group www-data:www-data then your current setting with user bacula in www-data group can not work in some cases. I would propose to do the opposite, assign the www-data user to the bacula group and tune ownership a bit.
# remove bacula user from www-data
gpasswd --delete www-data bacula
# add www-data user to bacula group
usermod -a -G bacula www-data
# set permissions for bacula files
chown root:bacula /etc/bacula/bacula-{dir,sd,fd}.conf /etc/bacula/bconsole.conf
# restart PHP-FPM (example for version 7.4):
systemctl restart php7.4-fpm
Once we have the permissions ready, next thing what could be checked is - what causes this timeout. The easiest way of checking is is to load the page that loads slowly and quickly at the same time see the system process list on the host with Bacularis. Just simple "ps auxfwww" is sufficient. This way we will see what causes that the process times out.
From my perspective it can be bconsole process but you will see. I know, you showed that in the command line this bconsole works well, thanks for this test, however using bconsole from the command line and using it in a web application can be a bit different in results, not because of permissions but because of other things.
Once we know the process that takes most of the time until timeout, we will know what to do. Also I would propose to consider adding to the web server log information about how much time every request takes. Information about how to do it you can find in this mail thread on this group:
https://groups.google.com/g/bacularis/c/x0NLsBD24IM
So, the access log will look like here:
127.0.0.1 - - [18/Jun/2024:09:11:46 +0200] "GET /api/v3/jobs/?limit=15000&director=darkstar-dir HTTP/1.1" 200 202822 "-" "-" 1148ms
127.0.0.1 - - [18/Jun/2024:09:11:47 +0200] "GET /api/v3/joblog/messages?director=darkstar-dir HTTP/1.1" 200 66 "-" "-" 247ms
and we see that the first request to get jobs took 1.1 seconds, and second to get joblog messages took 0.2 second. It helps to find which request is the slowest and causes time out.
For now that is all. Good luck with checking the above. Please let us know about the results.
Best regards,
Marcin Haba (gani)
--
You received this message because you are subscribed to the Google Groups "bacularis" group.
To unsubscribe from this group and stop receiving emails from it, send an email to bacularis+...@googlegroups.com.
To view this discussion on the web, visit https://groups.google.com/d/msgid/bacularis/b47bec63-ce75-4d4b-a90b-c51def9d49a6n%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
"Greater love hath no man than this, that a man lay down his life for his friends." Jesus Christ "Większej miłości nikt nie ma nad tę, jak gdy kto życie swoje kładzie za przyjaciół swoich." Jezus Chrystus
Message has been deleted
Message has been deleted
Message has been deleted
Message has been deleted
Romain Delmas
Jun 19, 2024, 4:55:33 AM6/19/24
to bacularis
Hello Marcin,
I dit all you proposed including permissions changings.
I tried to access to the jobs menu and you can find the result of the PS command :
bacula 73438 2.2 0.0 632528 12260 ? Ssl Jun17 59:29 /opt/bacula/bin/bacula-sd -dt -c /opt/bacula/etc/bacula-sd.conf
root 73451 0.0 0.0 238568 6148 ? Ssl Jun17 0:00 /opt/bacula/bin/bacula-fd -fP -c /opt/bacula/etc/bacula-fd.conf
bacula 73461 0.1 0.0 1673112 26820 ? Ssl Jun17 3:10 /opt/bacula/bin/bacula-dir -fP -c /opt/bacula/etc/bacula-dir.conf
postgres 81087 0.0 0.0 1150860 36120 ? Ss Jun17 0:11 /usr/lib/postgresql/13/bin/postgres -D /var/lib/postgresql/13/main -c config_file=/etc/postgresql/13/main/postgresql.conf
postgres 81089 0.0 0.1 1151064 180676 ? Ss Jun17 0:05 \_ postgres: 13/main: checkpointer
postgres 81090 0.0 0.0 1150996 11920 ? Ss Jun17 0:02 \_ postgres: 13/main: background writer
postgres 81091 0.0 0.0 1150860 4004 ? Ss Jun17 0:12 \_ postgres: 13/main: walwriter
postgres 81092 0.0 0.0 1151536 6540 ? Ss Jun17 0:03 \_ postgres: 13/main: autovacuum launcher
postgres 81093 0.0 0.0 68300 3720 ? Ss Jun17 0:09 \_ postgres: 13/main: stats collector
postgres 81094 0.0 0.0 1151420 4832 ? Ss Jun17 0:00 \_ postgres: 13/main: logical replication launcher
postgres 81105 0.0 0.0 1152072 10156 ? Ss Jun17 0:19 \_ postgres: 13/main: walsender repmgr 10.10.10.2(54358) streaming 12/DF7F670
postgres 148423 0.0 0.0 1152228 20172 ? Ss 09:01 0:00 \_ postgres: 13/main: bacula bacula [local] idle
postgres 149943 2.8 0.0 1152972 30424 ? Ss 09:59 0:02 \_ postgres: 13/main: bacula bacula [local] idle
root 149786 0.0 0.0 217960 31284 ? Ss 09:58 0:00 php-fpm: master process (/etc/php/8.3/fpm/php-fpm.conf)
www-data 149787 0.1 0.0 293080 33016 ? S 09:58 0:00 \_ php-fpm: pool www
www-data 149788 0.1 0.0 297276 36844 ? S 09:58 0:00 \_ php-fpm: pool www
www-data 149789 0.0 0.0 221096 36704 ? S 09:58 0:00 \_ php-fpm: pool www
www-data 149790 0.1 0.0 293876 37472 ? S 09:58 0:00 \_ php-fpm: pool www
www-data 150002 0.0 0.0 2480 516 ? S 10:01 0:00 | \_ sh -c sudo /usr/sbin/bconsole -c "/opt/bacula/etc/bconsole.conf" -D director-dir 2>&1 <<END_OF_DATA gui on .jobs quit END_OF_DATA
root 150003 0.0 0.0 7708 4628 ? S 10:01 0:00 | \_ sudo /usr/sbin/bconsole -c /opt/bacula/etc/bconsole.conf -D director-dir
root 150004 0.0 0.0 160740 8504 ? Sl 10:01 0:00 | \_ /usr/sbin/bconsole -c /opt/bacula/etc/bconsole.conf -D director-dir
www-data 149791 0.0 0.0 295200 39476 ? S 09:58 0:00 \_ php-fpm: pool www
root 149827 0.0 0.0 81164 2112 ? Ss 09:58 0:00 nginx: master process /usr/sbin/nginx -g daemon on; master_process on;
www-data 149828 0.0 0.0 82200 9752 ? S 09:58 0:00 \_ nginx: worker process
www-data 149829 0.0 0.0 81728 6536 ? S 09:58 0:00 \_ nginx: worker process
www-data 149830 0.0 0.0 81728 6536 ? S 09:58 0:00 \_ nginx: worker process
www-data 149831 0.0 0.0 81728 6536 ? S 09:58 0:00 \_ nginx: worker process
www-data 149832 0.0 0.0 81728 6536 ? S 09:58 0:00 \_ nginx: worker process
www-data 149833 0.0 0.0 81728 6536 ? S 09:58 0:00 \_ nginx: worker process
www-data 149834 0.0 0.0 81728 6540 ? S 09:58 0:00 \_ nginx: worker process
www-data 149835 0.0 0.0 81728 6540 ? S 09:58 0:00 \_ nginx: worker process
I also did the necesarry about the nginx loggings.
I tried to access to the configuration of the specific job :
127.0.0.1 - - [19/Jun/2024:10:24:06 +0200] "GET /api/v3/jobs/?limit=15000&director=director-dir HTTP/1.1"200 2054278 "-""-" "-" "15.319 sec."
PUBLIC_IP - admin [19/Jun/2024:10:24:17 +0200] "POST /panel/basic/ HTTP/1.1"200 2082 "https://MYSERVER/panel/basic/""Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:126.0) Gecko/20100101 Firefox/126.0" "-" "0.078 sec."
127.0.0.1 - - [19/Jun/2024:10:24:21 +0200] "GET /api/v3/joblog/messages?director=director-dir HTTP/1.1"200 57 "-""-" "-" "15.204 sec."
127.0.0.1 - - [19/Jun/2024:10:24:22 +0200] "GET /api/v3/jobs/show/?output=json&director=director-dir HTTP/1.1"200 179714 "-""-" "-" "30.526 sec."
PUBLIC_IP - - [19/Jun/2024:10:24:22 +0200] "GET /web/job/ HTTP/1.1"200 38767 "https://MYSERVER/web/""Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:126.0) Gecko/20100101 Firefox/126.0" "-" "30.629 sec."
PUBLIC_IP - - [19/Jun/2024:10:24:22 +0200] "POST /web/monitor/ HTTP/1.1"200 538875 "https://MYSERVER/web/job/""Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/125.0.0.0 Safari/537.36" "-" "30.817 sec."
PUBLIC_IP - - [19/Jun/2024:10:24:22 +0200] "GET /assets/eeeab548/favicon.ico HTTP/1.1"200 4286 "https://MYSERVER/web/job/""Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:126.0) Gecko/20100101 Firefox/126.0" "-" "0.000 sec."
127.0.0.1 - - [19/Jun/2024:10:24:37 +0200] "GET /api/v3/jobs/85179?director=director-dir HTTP/1.1"200 1165 "-""-" "-" "15.265 sec."
127.0.0.1 - - [19/Jun/2024:10:24:39 +0200] "GET /api/v3/jobs/?limit=15000&director=director-dir HTTP/1.1"200 2054278 "-""-" "-" "15.351 sec."
127.0.0.1 - - [19/Jun/2024:10:24:54 +0200] "GET /api/v3/joblog/messages?director=director-dir HTTP/1.1"200 57 "-""-" "-" "15.205 sec."
PUBLIC_IP - - [19/Jun/2024:10:24:54 +0200] "POST /web/monitor/ HTTP/1.1"200 538859 "https://MYSERVER/web/job/""Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:126.0) Gecko/20100101 Firefox/126.0" "-" "30.758 sec."
PUBLIC_IP - - [19/Jun/2024:10:24:54 +0200] "GET /themes/Baculum-v2/sort_desc.png HTTP/1.1"200 2908 "https://MYSERVER/assets/51aee402/baculum.css?ver=3.2.1""Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:126.0) Gecko/20100101 Firefox/126.0" "-" "0.000 sec."
PUBLIC_IP - - [19/Jun/2024:10:24:55 +0200] "GET /web/job/history/85179/ HTTP/1.1"499 0 "https://MYSERVER/web/job/""Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/125.0.0.0 Safari/537.36" "-" "49.446 sec."
PUBLIC_IP - - [19/Jun/2024:10:24:56 +0200] "GET /themes/Baculum-v2/weather_sunny.png HTTP/1.1"200 9858 "https://MYSERVER/web/job/""Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:126.0) Gecko/20100101 Firefox/126.0" "-" "0.000 sec."
PUBLIC_IP - - [19/Jun/2024:10:24:56 +0200] "GET /themes/Baculum-v2/weather_sun_behind_large_cloud.png HTTP/1.1"200 8420 "https://MYSERVER/web/job/""Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:126.0) Gecko/20100101 Firefox/126.0" "-" "0.000 sec."
PUBLIC_IP - - [19/Jun/2024:10:24:56 +0200] "GET /themes/Baculum-v2/weather_sun_behind_rain_cloud.png HTTP/1.1"200 9921 "https://MYSERVER/web/job/""Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:126.0) Gecko/20100101 Firefox/126.0" "-" "0.000 sec."
PUBLIC_IP - - [19/Jun/2024:10:24:56 +0200] "GET /themes/Baculum-v2/weather_sun_behind_small_cloud.png HTTP/1.1"200 9178 "https://MYSERVER/web/job/""Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:126.0) Gecko/20100101 Firefox/126.0" "-" "0.000 sec."
127.0.0.1 - - [19/Jun/2024:10:25:07 +0200] "GET /api/v3/jobs/show/?name=A_BACKUP_JOB&director=director-dir HTTP/1.1"200 6514 "-""-" "-" "30.422 sec."
127.0.0.1 - - [19/Jun/2024:10:25:23 +0200] "GET /api/v3/joblog/85179/?show_time=0&director=director-dir HTTP/1.1"200 3249 "-""-" "-" "15.287 sec."
127.0.0.1 - - [19/Jun/2024:10:25:38 +0200] "GET /api/v3/schedules/status/?job=A_BACKUP_JOB&days=90&limit=0&director=director-dir HTTP/1.1"200 24057 "-""-" "-" "15.307 sec."
127.0.0.1 - - [19/Jun/2024:10:25:53 +0200] "GET /api/v3/jobs/resnames?director=director-dir HTTP/1.1"200 3462 "-""-" "-" "15.235 sec."
127.0.0.1 - - [19/Jun/2024:10:26:09 +0200] "GET /api/v3/jobs/?limit=15000&director=director-dir HTTP/1.1"200 2054278 "-""-" "-" "15.343 sec."
PUBLIC_IP - - [19/Jun/2024:10:26:11 +0200] "GET /web/client/ HTTP/1.1"504 562 "https://MYSERVER/web/job/""Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/125.0.0.0 Safari/537.36" "-" "60.005 sec."
The host configuration :
- php8.3-fpm
- nginx 1.18.0
- postgresql 13.14
- bacularis 3.2.1
Thanks for your time and your expertise,
Best regards,
Romain
I dit all you proposed including permissions changings.
I tried to access to the jobs menu and you can find the result of the PS command :
bacula 73438 2.2 0.0 632528 12260 ? Ssl Jun17 59:29 /opt/bacula/bin/bacula-sd -dt -c /opt/bacula/etc/bacula-sd.conf
root 73451 0.0 0.0 238568 6148 ? Ssl Jun17 0:00 /opt/bacula/bin/bacula-fd -fP -c /opt/bacula/etc/bacula-fd.conf
bacula 73461 0.1 0.0 1673112 26820 ? Ssl Jun17 3:10 /opt/bacula/bin/bacula-dir -fP -c /opt/bacula/etc/bacula-dir.conf
postgres 81087 0.0 0.0 1150860 36120 ? Ss Jun17 0:11 /usr/lib/postgresql/13/bin/postgres -D /var/lib/postgresql/13/main -c config_file=/etc/postgresql/13/main/postgresql.conf
postgres 81089 0.0 0.1 1151064 180676 ? Ss Jun17 0:05 \_ postgres: 13/main: checkpointer
postgres 81090 0.0 0.0 1150996 11920 ? Ss Jun17 0:02 \_ postgres: 13/main: background writer
postgres 81091 0.0 0.0 1150860 4004 ? Ss Jun17 0:12 \_ postgres: 13/main: walwriter
postgres 81092 0.0 0.0 1151536 6540 ? Ss Jun17 0:03 \_ postgres: 13/main: autovacuum launcher
postgres 81093 0.0 0.0 68300 3720 ? Ss Jun17 0:09 \_ postgres: 13/main: stats collector
postgres 81094 0.0 0.0 1151420 4832 ? Ss Jun17 0:00 \_ postgres: 13/main: logical replication launcher
postgres 81105 0.0 0.0 1152072 10156 ? Ss Jun17 0:19 \_ postgres: 13/main: walsender repmgr 10.10.10.2(54358) streaming 12/DF7F670
postgres 148423 0.0 0.0 1152228 20172 ? Ss 09:01 0:00 \_ postgres: 13/main: bacula bacula [local] idle
postgres 149943 2.8 0.0 1152972 30424 ? Ss 09:59 0:02 \_ postgres: 13/main: bacula bacula [local] idle
root 149786 0.0 0.0 217960 31284 ? Ss 09:58 0:00 php-fpm: master process (/etc/php/8.3/fpm/php-fpm.conf)
www-data 149787 0.1 0.0 293080 33016 ? S 09:58 0:00 \_ php-fpm: pool www
www-data 149788 0.1 0.0 297276 36844 ? S 09:58 0:00 \_ php-fpm: pool www
www-data 149789 0.0 0.0 221096 36704 ? S 09:58 0:00 \_ php-fpm: pool www
www-data 149790 0.1 0.0 293876 37472 ? S 09:58 0:00 \_ php-fpm: pool www
www-data 150002 0.0 0.0 2480 516 ? S 10:01 0:00 | \_ sh -c sudo /usr/sbin/bconsole -c "/opt/bacula/etc/bconsole.conf" -D director-dir 2>&1 <<END_OF_DATA gui on .jobs quit END_OF_DATA
root 150003 0.0 0.0 7708 4628 ? S 10:01 0:00 | \_ sudo /usr/sbin/bconsole -c /opt/bacula/etc/bconsole.conf -D director-dir
root 150004 0.0 0.0 160740 8504 ? Sl 10:01 0:00 | \_ /usr/sbin/bconsole -c /opt/bacula/etc/bconsole.conf -D director-dir
www-data 149791 0.0 0.0 295200 39476 ? S 09:58 0:00 \_ php-fpm: pool www
root 149827 0.0 0.0 81164 2112 ? Ss 09:58 0:00 nginx: master process /usr/sbin/nginx -g daemon on; master_process on;
www-data 149828 0.0 0.0 82200 9752 ? S 09:58 0:00 \_ nginx: worker process
www-data 149829 0.0 0.0 81728 6536 ? S 09:58 0:00 \_ nginx: worker process
www-data 149830 0.0 0.0 81728 6536 ? S 09:58 0:00 \_ nginx: worker process
www-data 149831 0.0 0.0 81728 6536 ? S 09:58 0:00 \_ nginx: worker process
www-data 149832 0.0 0.0 81728 6536 ? S 09:58 0:00 \_ nginx: worker process
www-data 149833 0.0 0.0 81728 6536 ? S 09:58 0:00 \_ nginx: worker process
www-data 149834 0.0 0.0 81728 6540 ? S 09:58 0:00 \_ nginx: worker process
www-data 149835 0.0 0.0 81728 6540 ? S 09:58 0:00 \_ nginx: worker process
I also did the necesarry about the nginx loggings.
I tried to access to the configuration of the specific job :
127.0.0.1 - - [19/Jun/2024:10:24:06 +0200] "GET /api/v3/jobs/?limit=15000&director=director-dir HTTP/1.1"200 2054278 "-""-" "-" "15.319 sec."
PUBLIC_IP - admin [19/Jun/2024:10:24:17 +0200] "POST /panel/basic/ HTTP/1.1"200 2082 "https://MYSERVER/panel/basic/""Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:126.0) Gecko/20100101 Firefox/126.0" "-" "0.078 sec."
127.0.0.1 - - [19/Jun/2024:10:24:21 +0200] "GET /api/v3/joblog/messages?director=director-dir HTTP/1.1"200 57 "-""-" "-" "15.204 sec."
127.0.0.1 - - [19/Jun/2024:10:24:22 +0200] "GET /api/v3/jobs/show/?output=json&director=director-dir HTTP/1.1"200 179714 "-""-" "-" "30.526 sec."
PUBLIC_IP - - [19/Jun/2024:10:24:22 +0200] "GET /web/job/ HTTP/1.1"200 38767 "https://MYSERVER/web/""Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:126.0) Gecko/20100101 Firefox/126.0" "-" "30.629 sec."
PUBLIC_IP - - [19/Jun/2024:10:24:22 +0200] "POST /web/monitor/ HTTP/1.1"200 538875 "https://MYSERVER/web/job/""Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/125.0.0.0 Safari/537.36" "-" "30.817 sec."
PUBLIC_IP - - [19/Jun/2024:10:24:22 +0200] "GET /assets/eeeab548/favicon.ico HTTP/1.1"200 4286 "https://MYSERVER/web/job/""Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:126.0) Gecko/20100101 Firefox/126.0" "-" "0.000 sec."
127.0.0.1 - - [19/Jun/2024:10:24:37 +0200] "GET /api/v3/jobs/85179?director=director-dir HTTP/1.1"200 1165 "-""-" "-" "15.265 sec."
127.0.0.1 - - [19/Jun/2024:10:24:39 +0200] "GET /api/v3/jobs/?limit=15000&director=director-dir HTTP/1.1"200 2054278 "-""-" "-" "15.351 sec."
127.0.0.1 - - [19/Jun/2024:10:24:54 +0200] "GET /api/v3/joblog/messages?director=director-dir HTTP/1.1"200 57 "-""-" "-" "15.205 sec."
PUBLIC_IP - - [19/Jun/2024:10:24:54 +0200] "POST /web/monitor/ HTTP/1.1"200 538859 "https://MYSERVER/web/job/""Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:126.0) Gecko/20100101 Firefox/126.0" "-" "30.758 sec."
PUBLIC_IP - - [19/Jun/2024:10:24:54 +0200] "GET /themes/Baculum-v2/sort_desc.png HTTP/1.1"200 2908 "https://MYSERVER/assets/51aee402/baculum.css?ver=3.2.1""Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:126.0) Gecko/20100101 Firefox/126.0" "-" "0.000 sec."
PUBLIC_IP - - [19/Jun/2024:10:24:55 +0200] "GET /web/job/history/85179/ HTTP/1.1"499 0 "https://MYSERVER/web/job/""Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/125.0.0.0 Safari/537.36" "-" "49.446 sec."
PUBLIC_IP - - [19/Jun/2024:10:24:56 +0200] "GET /themes/Baculum-v2/weather_sunny.png HTTP/1.1"200 9858 "https://MYSERVER/web/job/""Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:126.0) Gecko/20100101 Firefox/126.0" "-" "0.000 sec."
PUBLIC_IP - - [19/Jun/2024:10:24:56 +0200] "GET /themes/Baculum-v2/weather_sun_behind_large_cloud.png HTTP/1.1"200 8420 "https://MYSERVER/web/job/""Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:126.0) Gecko/20100101 Firefox/126.0" "-" "0.000 sec."
PUBLIC_IP - - [19/Jun/2024:10:24:56 +0200] "GET /themes/Baculum-v2/weather_sun_behind_rain_cloud.png HTTP/1.1"200 9921 "https://MYSERVER/web/job/""Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:126.0) Gecko/20100101 Firefox/126.0" "-" "0.000 sec."
PUBLIC_IP - - [19/Jun/2024:10:24:56 +0200] "GET /themes/Baculum-v2/weather_sun_behind_small_cloud.png HTTP/1.1"200 9178 "https://MYSERVER/web/job/""Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:126.0) Gecko/20100101 Firefox/126.0" "-" "0.000 sec."
127.0.0.1 - - [19/Jun/2024:10:25:07 +0200] "GET /api/v3/jobs/show/?name=A_BACKUP_JOB&director=director-dir HTTP/1.1"200 6514 "-""-" "-" "30.422 sec."
127.0.0.1 - - [19/Jun/2024:10:25:23 +0200] "GET /api/v3/joblog/85179/?show_time=0&director=director-dir HTTP/1.1"200 3249 "-""-" "-" "15.287 sec."
127.0.0.1 - - [19/Jun/2024:10:25:38 +0200] "GET /api/v3/schedules/status/?job=A_BACKUP_JOB&days=90&limit=0&director=director-dir HTTP/1.1"200 24057 "-""-" "-" "15.307 sec."
127.0.0.1 - - [19/Jun/2024:10:25:53 +0200] "GET /api/v3/jobs/resnames?director=director-dir HTTP/1.1"200 3462 "-""-" "-" "15.235 sec."
127.0.0.1 - - [19/Jun/2024:10:26:09 +0200] "GET /api/v3/jobs/?limit=15000&director=director-dir HTTP/1.1"200 2054278 "-""-" "-" "15.343 sec."
PUBLIC_IP - - [19/Jun/2024:10:26:11 +0200] "GET /web/client/ HTTP/1.1"504 562 "https://MYSERVER/web/job/""Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/125.0.0.0 Safari/537.36" "-" "60.005 sec."
The host configuration :
- php8.3-fpm
- nginx 1.18.0
- postgresql 13.14
- bacularis 3.2.1
Thanks for your time and your expertise,
Best regards,
Romain
Marcin Haba
Jun 19, 2024, 6:07:30 AM6/19/24
to Romain Delmas, bacularis
Hello Romain,
Thanks for providing more details. Yes, the request time does not look good.
Could I ask you about checking how much time takes this command? You can just copy paste it to command line on the root account:
time -p sudo -u www-data sudo /usr/sbin/bconsole -c /opt/bacula/etc/bconsole.conf -D director-dir 2>&1 <<END_OF_DATA
Thanks for providing more details. Yes, the request time does not look good.
Could I ask you about checking how much time takes this command? You can just copy paste it to command line on the root account:
time -p sudo -u www-data sudo /usr/sbin/bconsole -c /opt/bacula/etc/bconsole.conf -D director-dir 2>&1 <<END_OF_DATA
gui on
.jobs
quit
END_OF_DATA
You can send us here only three last output lines that are timing values.
Also please try this command for checking the database connection time:
time -p psql -U BACULA_DB_USER BACULA_DB_NAME -h DB_ADDRESS_USED_BY_BACULARIS -c 'SELECT * FROM Job LIMIT 15000'
BACULA_DB_USER - Bacula database user
BACULA_DB_NAME - Bacula database name
DB_ADDRESS_USED_BY_BACULARIS - Database address used by Bacularis
Thanks in advance for sharing results with us.
Info to Everybody: for sending messages on the group, since yesterday this Bacularis user group experiences some problems that emails instead go to the list directly, they are blocked in the 'Pending' folder and they are waiting on acceptance. I don't know why it happens. I am observing this situation carefully.
Also please try this command for checking the database connection time:
time -p psql -U BACULA_DB_USER BACULA_DB_NAME -h DB_ADDRESS_USED_BY_BACULARIS -c 'SELECT * FROM Job LIMIT 15000'
BACULA_DB_USER - Bacula database user
BACULA_DB_NAME - Bacula database name
DB_ADDRESS_USED_BY_BACULARIS - Database address used by Bacularis
Thanks in advance for sharing results with us.
Info to Everybody: for sending messages on the group, since yesterday this Bacularis user group experiences some problems that emails instead go to the list directly, they are blocked in the 'Pending' folder and they are waiting on acceptance. I don't know why it happens. I am observing this situation carefully.
Best regards,
Marcin Haba (gani)
--
You received this message because you are subscribed to the Google Groups "bacularis" group.
To unsubscribe from this group and stop receiving emails from it, send an email to bacularis+...@googlegroups.com.
To view this discussion on the web, visit https://groups.google.com/d/msgid/bacularis/7f1e79c5-7440-42ad-8dfe-16fff21e35c0n%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
Message has been deleted
Message has been deleted
Message has been deleted
Message has been deleted
Message has been deleted
Message has been deleted
Romain Delmas
Jun 19, 2024, 8:43:35 AM6/19/24
to bacularis
Yo,
The result of the first command :
:~# time -p sudo -u www-data sudo /usr/sbin/bconsole -c /opt/bacula/etc/bconsole.conf -D director-dir 2>&1 <<END_OF_DATA
gui on
.jobs
quit
END_OF_DATA
real 15.18
user 0.04
sys 0.01
The result of the second command :
The result of the first command :
:~# time -p sudo -u www-data sudo /usr/sbin/bconsole -c /opt/bacula/etc/bconsole.conf -D director-dir 2>&1 <<END_OF_DATA
gui on
.jobs
quit
END_OF_DATA
real 15.18
user 0.04
sys 0.01
The result of the second command :
:~$ time -p psql -U
BACULA_DB_USER BACULA_DB_NAME -h
DB_ADDRESS_USED_BY_BACULARIS -c 'SELECT * FROM Job LIMIT 15000'
Password for user BACULA_DB_USER :
real 5.16
user 0.16
sys 0.01
Thanks again for your time :)
Password for user BACULA_DB_USER :
real 5.16
user 0.16
sys 0.01
Thanks again for your time :)
Kind,
Romain
Romain Delmas
Jun 19, 2024, 8:45:21 AM6/19/24
to bacularis
Hello Marcin,
real 5.16
user 0.16
sys 0.01
Here there all the results commands :
:~$ time -p psql -U BACULA_DB_USER BACULA_DB_NAME -h DB_ADDRESS_USED_BY_BACULARIS -c 'SELECT * FROM Job LIMIT 15000'
Password for user bacula:
:~$ time -p psql -U BACULA_DB_USER BACULA_DB_NAME -h DB_ADDRESS_USED_BY_BACULARIS -c 'SELECT * FROM Job LIMIT 15000'
Password for user bacula:
real 5.16
user 0.16
sys 0.01
real 2.85
user 0.14
sys 0.01
user 0.14
sys 0.01
:~$ time -p psql -U BACULA_DB_USER BACULA_DB_NAME -h DB_ADDRESS_USED_BY_BACULARIS -c 'SELECT * FROM Job LIMIT 15000'
real 15.18
user 0.04
sys 0.01
user 0.04
sys 0.01
real 15.19
user 0.03
sys 0.02
user 0.03
sys 0.02
real 15.19
user 0.04
sys 0.02
user 0.04
sys 0.02
Thanks again for your time and expertise,
Kind to you,
Romain
On Wednesday, June 19, 2024 at 12:07:30 PM UTC+2 Marcin Haba wrote:
Message has been deleted
Message has been deleted
Message has been deleted
Message has been deleted
Romain Delmas
Jun 19, 2024, 1:05:27 PM6/19/24
to bacularis
Hi,
real 5.16
user 0.16
sys 0.01
i tried to have more data than :
user@:~$ time -p psql -U BACULA_DB_USER BACULA_DB_NAME -h DB_ADDRESS_USED_BY_BACULARIS -c 'SELECT * FROM Job LIMIT 15000'
Password for bacula_user:
Password for bacula_user:
real 5.16
user 0.16
sys 0.01
real 2.85
user 0.14
sys 0.01
user 0.14
sys 0.01
root@:~# time -p sudo -u www-data sudo /usr/sbin/bconsole -c /opt/bacula/etc/bconsole.conf -D director-dir 2>&1 <<END_OF_DATA
real 15.18
user 0.04
sys 0.01
user 0.04
sys 0.01
real 15.19
user 0.03
sys 0.02
user 0.03
sys 0.02
real 15.19
user 0.04
sys 0.02
user 0.04
sys 0.02
For example, with auditd :
node=MY_WEBSERVER type=PROCTITLE msg=audit(06/19/2024 11:56:36.489:406489) : proctitle=php-fpm: pool www
node=MY_WEBSERVER type=SYSCALL msg=audit(06/19/2024 11:56:36.489:406489) : arch=x86_64 syscall=prctl success=no exit=EINVAL(Invalid argument) a0=unknown-prctl-option(0x53564d41) a1=0x0 a2=0x7fe54c5fe000 a3=0x602000 items=0 ppid=149786 pid=151022 auid=unset uid=www-data gid=www-data euid=www-data suid=www-data fsuid=www-data egid=www-data sgid=www-data fsgid=www-data tty=(none) ses=unset comm=php-fpm8.3 exe=/usr/sbin/php-fpm8.3 subj=unconfined key=audit_syscall
When i tried :
curl -v -X GET 'https://MYWEBSERVER:MYPORT/oauth/authorize?response_type=code&client_id=USER_ID&scope=jobs&redirect_uri=https:// MYWEBSERVER:MYPORT /web/redirect' -H 'Content-Type: application/x-www-form-urlencoded'
with an user who has the right scope, i get : HTTP/1.1 401 Unauthorized
but the same command with the admin client_id : HTTP/1.1 302 Found and https://MYWEBSERVER:MYPORT/web/redirect?code=XXX
node=MY_WEBSERVER type=PROCTITLE msg=audit(06/19/2024 11:56:36.489:406489) : proctitle=php-fpm: pool www
node=MY_WEBSERVER type=SYSCALL msg=audit(06/19/2024 11:56:36.489:406489) : arch=x86_64 syscall=prctl success=no exit=EINVAL(Invalid argument) a0=unknown-prctl-option(0x53564d41) a1=0x0 a2=0x7fe54c5fe000 a3=0x602000 items=0 ppid=149786 pid=151022 auid=unset uid=www-data gid=www-data euid=www-data suid=www-data fsuid=www-data egid=www-data sgid=www-data fsgid=www-data tty=(none) ses=unset comm=php-fpm8.3 exe=/usr/sbin/php-fpm8.3 subj=unconfined key=audit_syscall
When i tried :
curl -v -X GET 'https://MYWEBSERVER:MYPORT/oauth/authorize?response_type=code&client_id=USER_ID&scope=jobs&redirect_uri=https:// MYWEBSERVER:MYPORT /web/redirect' -H 'Content-Type: application/x-www-form-urlencoded'
with an user who has the right scope, i get : HTTP/1.1 401 Unauthorized
but the same command with the admin client_id : HTTP/1.1 302 Found and https://MYWEBSERVER:MYPORT/web/redirect?code=XXX
Best regards,
Romain
Marcin Haba
Jun 19, 2024, 1:57:12 PM6/19/24
to Romain Delmas, bacularis
Hello Romain,
Thank you for providing more details.
For this request:
Thank you for providing more details.
For this request:
curl -v -X GET 'https://MYWEBSERVER:MYPORT/oauth/authorize?response_type=code&client_id=USER_ID&scope=jobs&redirect_uri=https:// MYWEBSERVER:MYPORT /web/redirect' -H 'Content-Type: application/x-www-form-urlencoded'
this "HTTP/1.1 401 Unauthorized" error for /oauth/authorize endpoint can happen in two main cases:
1) when the provided client_id does not exist in the Bacularis API. It is easy to check in the API panel
2) when the provided redirect_uri does not match the redirect_uri defined for the account with the given client_id. It is also possible to check in the Baculairs API panel.
In this address above I see that there are spaces in the redirect_uri parameter:
redirect_uri=https:// MYWEBSERVER:MYPORT /web/redirect
Could you confirm that it happened when you masked the address:port by pasting MYWEBSERVER:MYPORT? Or the spaces existed during the curl execution?
For the time results problem it looks that something is wrong on the Bacula side because 15 seconds to list jobs from configuration is too much. It should take 0.1 second or less.
1) when the provided client_id does not exist in the Bacularis API. It is easy to check in the API panel
2) when the provided redirect_uri does not match the redirect_uri defined for the account with the given client_id. It is also possible to check in the Baculairs API panel.
In this address above I see that there are spaces in the redirect_uri parameter:
redirect_uri=https:// MYWEBSERVER:MYPORT /web/redirect
Could you confirm that it happened when you masked the address:port by pasting MYWEBSERVER:MYPORT? Or the spaces existed during the curl execution?
For the time results problem it looks that something is wrong on the Bacula side because 15 seconds to list jobs from configuration is too much. It should take 0.1 second or less.
:~# time -p sudo -u www-data sudo /usr/sbin/bconsole -c /opt/bacula/etc/bconsole.conf -D director-dir 2>&1 <<END_OF_DATA
gui on
.jobs
quit
END_OF_DATA
.jobs
quit
END_OF_DATA
real 15.18
user 0.04
sys 0.01
user 0.04
sys 0.01
As I proposed previously, setting the debug for the Director and bconsole can show where exactly this command slows down.
In the auditd I am not sure if it is fine or not. My private feeling is that this auditd is not a problem in this case, but I can be wrong.
Thanks in advance for sharing with us the results.
Best regards,
Marcin Haba (gani)
To view this discussion on the web, visit https://groups.google.com/d/msgid/bacularis/8f9d15a2-66a7-4462-b606-7e472d210d9en%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
Message has been deleted
Romain Delmas
Jun 20, 2024, 8:58:16 PM6/20/24
to bacularis
Hi,
gui on
.jobs
quit
END_OF_DATA"
Connecting to Director MY_WEBSERVER:MY_WEBSERVER_PORT
bconsole: bsockcore.c:357-0 Current MY_WEBSERVER_PUBLIC_IP:MY_WEBSERVER_PORT All MY_WEBSERVER_PUBLIC_IP:MY_WEBSERVER_PORT
bconsole: bsockcore.c:290-0 who=Director daemon host=MY_WEBSERVER port=MY_WEBSERVER_PORT
bconsole: bsockcore.c:476-0 OK connected to server Director daemon MY_WEBSERVER:MY_WEBSERVER_PORT. socket=MY_WEBSERVER_PUBLIC_IP.57630:MY_WEBSERVER_PUBLIC_IP.MY_WEBSERVER_PORT s=0x560a325ee198
bconsole: authenticatebase.cc:339-0 TLSPSK Local need 202
bconsole: authenticatebase.cc:371-0 TLSPSK Remote need 202
bconsole: authenticatebase.cc:582-0 TLSPSK Start TLS
bconsole: bnet.c:153-0 TLS client negotiation established.
bconsole: cram-md5.c:132-0 cram-get received: auth cram-md5 <631475260.1718871721@director-dir> ssl=2
bconsole: cram-md5.c:156-0 sending resp to challenge: 88wraQoRe+/Y8k+T/+VoQC
bconsole: cram-md5.c:75-0 send: auth cram-md5 challenge <2090792402.1718871721@bconsole> ssl=2
bconsole: cram-md5.c:94-0 Authenticate OK HH+x6Q+Cd4JzS7/iWncEXD
bconsole: authenticate.c:293-0 >dird: 1000 OK auth
bconsole: authenticate.c:300-0 <dird: 1000 OK: 10002 director-dir Version: 15.0.2 (21 March 2024)
1000 OK: 10002 director-dir Version: 15.0.2 (21 March 2024)
bconsole: console.c:1385-0 Opened connection with Director daemon
Enter a period to cancel a command.
gui on
bconsole: console.c:376-0 Got poll BNET_EOD
.jobs
(...)
bconsole: console.c:376-0 Got poll BNET_EOD
quit
bconsole: lockmgr.c:792-0 Exit check_deadlock.
:~$ sudo -u www-data bash -c "sudo /usr/sbin/bconsole -d 200,all -D director-dir 2>&1 <<END_OF_DATA
gui on
.jobs
quit
END_OF_DATA"
Connecting to Director MY_WEBSERVER:MY_WEBSERVER_PORT
bconsole: bsockcore.c:357-0 Current MY_WEBSERVER_PUBLIC_IP:MY_WEBSERVER_PORT All MY_WEBSERVER_PUBLIC_IP:MY_WEBSERVER_PORT
bconsole: bsockcore.c:290-0 who=Director daemon host=MY_WEBSERVER port=MY_WEBSERVER_PORT
bconsole: bsockcore.c:476-0 OK connected to server Director daemon MY_WEBSERVER:MY_WEBSERVER_PORT. socket=MY_WEBSERVER_PUBLIC_IP.38384:MY_WEBSERVER_PUBLIC_IP.MY_WEBSERVER_PORT s=0x55714f154198
bconsole: authenticatebase.cc:339-0 TLSPSK Local need 202
bconsole: authenticatebase.cc:371-0 TLSPSK Remote need 202
bconsole: authenticatebase.cc:582-0 TLSPSK Start TLS
bconsole: bnet.c:153-0 TLS client negotiation established.
bconsole: cram-md5.c:132-0 cram-get received: auth cram-md5 <1919533814.1718901630@director-dir> ssl=2
bconsole: cram-md5.c:156-0 sending resp to challenge: h/8aK1oHI4J4U9/SmF40mD
bconsole: cram-md5.c:75-0 send: auth cram-md5 challenge <1825917172.1718901630@bconsole> ssl=2
bconsole: cram-md5.c:94-0 Authenticate OK xg+kZV8heS/qm++eT//sqB
bconsole: authenticate.c:293-0 >dird: 1000 OK auth
bconsole: authenticate.c:300-0 <dird: 1000 OK: 10002 director-dir Version: 15.0.2 (21 March 2024)
1000 OK: 10002 director-dir Version: 15.0.2 (21 March 2024)
bconsole: console.c:1385-0 Opened connection with Director daemon
Enter a period to cancel a command.
gui on
bconsole: console.c:376-0 Got poll BNET_EOD
.jobs
(...)
bconsole: console.c:376-0 Got poll BNET_EOD
quit
bconsole: lockmgr.c:792-0 Exit check_deadlock.
Yes, the space was a consequence of masking the address:port by pasting MYWEBSERVER:MYPORT... Sorry for that !
I'll see to activate the debug mode (only with the -d option ? https://www.bacula.org/15.0.x-manuals/en/main/main.pdf p. 678)
Director {
Messages = "Daemon"
}
Messages {
Name = "Daemon"
Append = /opt/bacula/working/bacula.log = All
Console = All, !Skipped
Catalog = All, Events
}
Messages = "Daemon"
}
Messages {
Name = "Daemon"
Append = /opt/bacula/working/bacula.log = All
Console = All, !Skipped
Catalog = All, Events
}
I already tried these commands :
:~$ sudo -u www-data bash -c "sudo /usr/sbin/bconsole -d 200 -D director-dir 2>&1 <<END_OF_DATA
:~$ sudo -u www-data bash -c "sudo /usr/sbin/bconsole -d 200 -D director-dir 2>&1 <<END_OF_DATA
gui on
.jobs
quit
END_OF_DATA"
Connecting to Director MY_WEBSERVER:MY_WEBSERVER_PORT
bconsole: bsockcore.c:357-0 Current MY_WEBSERVER_PUBLIC_IP:MY_WEBSERVER_PORT All MY_WEBSERVER_PUBLIC_IP:MY_WEBSERVER_PORT
bconsole: bsockcore.c:290-0 who=Director daemon host=MY_WEBSERVER port=MY_WEBSERVER_PORT
bconsole: bsockcore.c:476-0 OK connected to server Director daemon MY_WEBSERVER:MY_WEBSERVER_PORT. socket=MY_WEBSERVER_PUBLIC_IP.57630:MY_WEBSERVER_PUBLIC_IP.MY_WEBSERVER_PORT s=0x560a325ee198
bconsole: authenticatebase.cc:339-0 TLSPSK Local need 202
bconsole: authenticatebase.cc:371-0 TLSPSK Remote need 202
bconsole: authenticatebase.cc:582-0 TLSPSK Start TLS
bconsole: bnet.c:153-0 TLS client negotiation established.
bconsole: cram-md5.c:132-0 cram-get received: auth cram-md5 <631475260.1718871721@director-dir> ssl=2
bconsole: cram-md5.c:156-0 sending resp to challenge: 88wraQoRe+/Y8k+T/+VoQC
bconsole: cram-md5.c:75-0 send: auth cram-md5 challenge <2090792402.1718871721@bconsole> ssl=2
bconsole: cram-md5.c:94-0 Authenticate OK HH+x6Q+Cd4JzS7/iWncEXD
bconsole: authenticate.c:293-0 >dird: 1000 OK auth
bconsole: authenticate.c:300-0 <dird: 1000 OK: 10002 director-dir Version: 15.0.2 (21 March 2024)
1000 OK: 10002 director-dir Version: 15.0.2 (21 March 2024)
bconsole: console.c:1385-0 Opened connection with Director daemon
Enter a period to cancel a command.
gui on
bconsole: console.c:376-0 Got poll BNET_EOD
.jobs
(...)
bconsole: console.c:376-0 Got poll BNET_EOD
quit
bconsole: lockmgr.c:792-0 Exit check_deadlock.
:~$ sudo -u www-data bash -c "sudo /usr/sbin/bconsole -d 200,all -D director-dir 2>&1 <<END_OF_DATA
gui on
.jobs
quit
END_OF_DATA"
Connecting to Director MY_WEBSERVER:MY_WEBSERVER_PORT
bconsole: bsockcore.c:357-0 Current MY_WEBSERVER_PUBLIC_IP:MY_WEBSERVER_PORT All MY_WEBSERVER_PUBLIC_IP:MY_WEBSERVER_PORT
bconsole: bsockcore.c:290-0 who=Director daemon host=MY_WEBSERVER port=MY_WEBSERVER_PORT
bconsole: bsockcore.c:476-0 OK connected to server Director daemon MY_WEBSERVER:MY_WEBSERVER_PORT. socket=MY_WEBSERVER_PUBLIC_IP.38384:MY_WEBSERVER_PUBLIC_IP.MY_WEBSERVER_PORT s=0x55714f154198
bconsole: authenticatebase.cc:339-0 TLSPSK Local need 202
bconsole: authenticatebase.cc:371-0 TLSPSK Remote need 202
bconsole: authenticatebase.cc:582-0 TLSPSK Start TLS
bconsole: bnet.c:153-0 TLS client negotiation established.
bconsole: cram-md5.c:132-0 cram-get received: auth cram-md5 <1919533814.1718901630@director-dir> ssl=2
bconsole: cram-md5.c:156-0 sending resp to challenge: h/8aK1oHI4J4U9/SmF40mD
bconsole: cram-md5.c:75-0 send: auth cram-md5 challenge <1825917172.1718901630@bconsole> ssl=2
bconsole: cram-md5.c:94-0 Authenticate OK xg+kZV8heS/qm++eT//sqB
bconsole: authenticate.c:293-0 >dird: 1000 OK auth
bconsole: authenticate.c:300-0 <dird: 1000 OK: 10002 director-dir Version: 15.0.2 (21 March 2024)
1000 OK: 10002 director-dir Version: 15.0.2 (21 March 2024)
bconsole: console.c:1385-0 Opened connection with Director daemon
Enter a period to cancel a command.
gui on
bconsole: console.c:376-0 Got poll BNET_EOD
.jobs
(...)
bconsole: console.c:376-0 Got poll BNET_EOD
quit
bconsole: lockmgr.c:792-0 Exit check_deadlock.
Thanks again,
Yours,
Romain
Marcin Haba
Jun 20, 2024, 9:09:29 PM6/20/24
to Romain Delmas, bacularis
Hello Romain,
Thanks for your tests and showing us results. Yes, the research is going in a good direction, I think. For the debug, I am afraid that the debug level 200 on the bconsole side may be not sufficient to see anything. Could you please add -d900 parameter to bconsole command to see where exactly it hangs? Also useful might be to add -dt parameter to see the timestamps.
# time -p sudo -u www-data sudo /usr/sbin/bconsole -dt -d900 -c /opt/bacula/etc/bconsole.conf -D director-dir 2>&1 <<END_OF_DATA
Thanks for your tests and showing us results. Yes, the research is going in a good direction, I think. For the debug, I am afraid that the debug level 200 on the bconsole side may be not sufficient to see anything. Could you please add -d900 parameter to bconsole command to see where exactly it hangs? Also useful might be to add -dt parameter to see the timestamps.
# time -p sudo -u www-data sudo /usr/sbin/bconsole -dt -d900 -c /opt/bacula/etc/bconsole.conf -D director-dir 2>&1 <<END_OF_DATA
gui on
.jobs
quit
END_OF_DATA
After this test you can try to add to the Director debug like this below and repeat the above command to see what happens on the Director side too. This bconsole command for debug is this:
# Before test please enable debug
setdebug level=900 trace=1 dir
# After test please disable debug
setdebug level=0 trace=0 dir
The debug log you will find in /opt/bacula/working/director-dir.trace
Thanks.
# Before test please enable debug
setdebug level=900 trace=1 dir
# After test please disable debug
setdebug level=0 trace=0 dir
The debug log you will find in /opt/bacula/working/director-dir.trace
Thanks.
Best regards,
Marcin Haba (gani)
To view this discussion on the web, visit https://groups.google.com/d/msgid/bacularis/ba9cf889-678b-437d-aa2e-907c89659799n%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
Romain Delmas
Jun 21, 2024, 3:44:12 AM6/21/24
to bacularis
Here the first command :
:~$ time -p sudo -u www-data sudo /usr/sbin/bconsole -dt -d900 -c /opt/bacula/etc/bconsole.conf -D director-dir 2>&1 <<END_OF_DATA
gui on
.jobs
quit
END_OF_DATA
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1596-0 parse_config pass 1
21-Jun-2024 09:12:16 bconsole: lex.c:254-0 Open config file: /opt/bacula/etc/bconsole.conf
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=0 pass=1 got token=T_EOL
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=0 pass=1 got token=T_EOL
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=0 pass=1 got token=T_EOL
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=0 pass=1 got token=T_EOL
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=0 pass=1 got token=T_EOL
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=0 pass=1 got token=T_EOL
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=0 pass=1 got token=T_EOL
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=0 pass=1 got token=T_IDENTIFIER
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=Name def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=Description def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=DirPort def=yes defval=MY_WEBSERVER_PORT
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=Address def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=Password def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=FipsRequire def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=TlsAuthenticate def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=TlsEnable def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=TlsPskEnable def=yes defval=1
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=TlsRequire def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=TlsCaCertificateFile def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=TlsCaCertificateDir def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=TlsCertificate def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=TlsKey def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=HeartbeatInterval def=yes defval=300
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=HistoryFile def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=HistoryFileSize def=yes defval=100
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=1 got token=T_BOB
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=1 got token=T_EOL
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=1 got token=T_IDENTIFIER
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1678-0 in T_IDENT got token=T_EQUALS
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1684-0 calling handler for Name
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=1 got token=T_IDENTIFIER
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1678-0 in T_IDENT got token=T_EQUALS
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1684-0 calling handler for DirPort
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=1 got token=T_IDENTIFIER
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1678-0 in T_IDENT got token=T_EQUALS
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1684-0 calling handler for Address
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=1 got token=T_IDENTIFIER
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1678-0 in T_IDENT got token=T_EQUALS
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1684-0 calling handler for Password
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=1 got token=T_IDENTIFIER
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1678-0 in T_IDENT got token=T_EQUALS
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1684-0 calling handler for TlsEnable
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=1 got token=T_IDENTIFIER
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1678-0 in T_IDENT got token=T_EQUALS
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1684-0 calling handler for TlsRequire
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=1 got token=T_IDENTIFIER
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1678-0 in T_IDENT got token=T_EQUALS
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1684-0 calling handler for TlsCertificate
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=1 got token=T_IDENTIFIER
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1678-0 in T_IDENT got token=T_EQUALS
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1684-0 calling handler for TlsCaCertificateFile
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=1 got token=T_IDENTIFIER
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1678-0 in T_IDENT got token=T_EQUALS
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1684-0 calling handler for TlsKey
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=1 got token=T_EOB
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1707-0 T_EOB => define new resource
21-Jun-2024 09:12:16 bconsole: parse_conf.c:255-0 Inserted res: director-dir index=1
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=0 pass=1 got token=T_EOL
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1596-0 parse_config pass 2
21-Jun-2024 09:12:16 bconsole: lex.c:254-0 Open config file: /opt/bacula/etc/bconsole.conf
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=0 pass=2 got token=T_EOL
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=0 pass=2 got token=T_EOL
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=0 pass=2 got token=T_EOL
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=0 pass=2 got token=T_EOL
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=0 pass=2 got token=T_EOL
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=0 pass=2 got token=T_EOL
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=0 pass=2 got token=T_EOL
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=0 pass=2 got token=T_IDENTIFIER
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=Name def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=Description def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=DirPort def=yes defval=MY_WEBSERVER_PORT
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=Address def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=Password def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=FipsRequire def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=TlsAuthenticate def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=TlsEnable def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=TlsPskEnable def=yes defval=1
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=TlsRequire def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=TlsCaCertificateFile def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=TlsCaCertificateDir def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=TlsCertificate def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=TlsKey def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=HeartbeatInterval def=yes defval=300
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=HistoryFile def=no defval=0
21-Jun-2024 09:12:16 bconsole: parse_conf.c:274-0 Item=HistoryFileSize def=yes defval=100
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=2 got token=T_BOB
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=2 got token=T_EOL
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=2 got token=T_IDENTIFIER
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1678-0 in T_IDENT got token=T_EQUALS
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1684-0 calling handler for Name
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=2 got token=T_IDENTIFIER
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1678-0 in T_IDENT got token=T_EQUALS
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1684-0 calling handler for DirPort
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=2 got token=T_IDENTIFIER
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1678-0 in T_IDENT got token=T_EQUALS
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1684-0 calling handler for Address
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=2 got token=T_IDENTIFIER
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1678-0 in T_IDENT got token=T_EQUALS
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1684-0 calling handler for Password
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=2 got token=T_IDENTIFIER
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1678-0 in T_IDENT got token=T_EQUALS
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1684-0 calling handler for TlsEnable
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=2 got token=T_IDENTIFIER
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1678-0 in T_IDENT got token=T_EQUALS
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1684-0 calling handler for TlsRequire
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=2 got token=T_IDENTIFIER
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1678-0 in T_IDENT got token=T_EQUALS
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1684-0 calling handler for TlsCertificate
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=2 got token=T_IDENTIFIER
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1678-0 in T_IDENT got token=T_EQUALS
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1684-0 calling handler for TlsCaCertificateFile
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=2 got token=T_IDENTIFIER
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1678-0 in T_IDENT got token=T_EQUALS
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1684-0 calling handler for TlsKey
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=1 pass=2 got token=T_EOB
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1707-0 T_EOB => define new resource
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1622-0 parse state=0 pass=2 got token=T_EOL
Director: name=director-dir address=MY_WEBSERVER DIRport=MY_WEBSERVER_PORT histfile=
21-Jun-2024 09:12:16 bconsole: parse_conf.c:1744-0 Leave parse_config()
21-Jun-2024 09:12:16 bconsole: watchdog.c:82-0 Initialising NicB-hacked watchdog thread
Connecting to Director MY_WEBSERVER:MY_WEBSERVER_PORT
21-Jun-2024 09:12:16 bconsole: watchdog.c:196-0 Registered watchdog 55cbc59c3c48, interval 15 one shot
21-Jun-2024 09:12:16 bconsole: btimers.c:145-0 Start thread timer 55cbc59c04e8 tid 7fe229633780 for 15 secs.
21-Jun-2024 09:12:31 bconsole: btimers.c:242-0 thread timer 55cbc59c3c48 kill thread tid=7fe229633780 at 1718953951.
21-Jun-2024 09:12:31 bconsole: signal.c:125-0 sig=12 User-defined signal 2
21-Jun-2024 09:12:31 bconsole: bsockcore.c:357-0 Current MY_WEBSERVER_PUBLIC_IP:MY_WEBSERVER_PORT All MY_WEBSERVER_PUBLIC_IP:MY_WEBSERVER_PORT
21-Jun-2024 09:12:31 bconsole: bsockcore.c:290-0 who=Director daemon host=MY_WEBSERVER port=MY_WEBSERVER_PORT
21-Jun-2024 09:12:31 bconsole: bsockcore.c:476-0 OK connected to server Director daemon MY_WEBSERVER:MY_WEBSERVER_PORT. socket=MY_WEBSERVER_PUBLIC_IP.36076:MY_WEBSERVER_PUBLIC_IP.MY_WEBSERVER_PORT s=0x55cbc59c9a08
21-Jun-2024 09:12:31 bconsole: btimers.c:225-0 Stop thread timer 55cbc59c04e8 tid=7fe229633780.
21-Jun-2024 09:12:31 bconsole: watchdog.c:226-0 Unregistered inactive watchdog 55cbc59c3c48
21-Jun-2024 09:12:31 bconsole: authenticatebase.cc:339-0 TLSPSK Local need 202
21-Jun-2024 09:12:31 bconsole: watchdog.c:196-0 Registered watchdog 55cbc59c3c48, interval 1500 one shot
21-Jun-2024 09:12:31 bconsole: btimers.c:176-0 Start bsock timer 55cbc59c04e8 tid=7fe229633780 for 1500 secs at 1718953951
21-Jun-2024 09:12:31 bconsole: authenticatebase.cc:371-0 TLSPSK Remote need 202
21-Jun-2024 09:12:31 bconsole: authenticatebase.cc:582-0 TLSPSK Start TLS
21-Jun-2024 09:12:31 bconsole: tls.c:621-0 Check subject name name
21-Jun-2024 09:12:31 bconsole: bnet.c:153-0 TLS client negotiation established.
21-Jun-2024 09:12:31 bconsole: cram-md5.c:132-0 cram-get received: auth cram-md5 <2028598241.1718953951@director-dir> ssl=2
21-Jun-2024 09:12:31 bconsole: cram-md5.c:156-0 sending resp to challenge: oSAyNylUny5uTQYOP+0ogC
21-Jun-2024 09:12:31 bconsole: cram-md5.c:75-0 send: auth cram-md5 challenge <1170364534.1718953951@bconsole> ssl=2
21-Jun-2024 09:12:31 bconsole: cram-md5.c:94-0 Authenticate OK U79wO7/hCUBoP+5XR5d3CB
21-Jun-2024 09:12:31 bconsole: authenticate.c:293-0 >dird: 1000 OK auth
21-Jun-2024 09:12:31 bconsole: authenticate.c:300-0 <dird: 1000 OK: 10002 director-dir Version: 15.0.2 (21 March 2024)
1000 OK: 10002 director-dir Version: 15.0.2 (21 March 2024)
21-Jun-2024 09:12:31 bconsole: watchdog.c:217-0 Unregistered watchdog 55cbc59c3c48
21-Jun-2024 09:12:31 bconsole: console.c:1385-0 Opened connection with Director daemon
Enter a period to cancel a command.
gui on
.jobs
(...)
21-Jun-2024 09:12:31 bconsole: console.c:376-0 Got poll BNET_EOD
quit
21-Jun-2024 09:12:31 bconsole: bsock.c:811-0 0x55cbc59c9a08 BSOCK::close()
21-Jun-2024 09:12:31 bconsole: bsockcore.c:1052-0 BSOCKCORE::close()
21-Jun-2024 09:12:31 bconsole: watchdog.c:196-0 Registered watchdog 55cbc59c3c48, interval 120 one shot
21-Jun-2024 09:12:31 bconsole: btimers.c:176-0 Start bsock timer 55cbc59c04e8 tid=7fe229633780 for 120 secs at 1718953951
21-Jun-2024 09:12:31 bconsole: btimers.c:212-0 Stop bsock timer 55cbc59c04e8 tid=7fe229633780 at 1718953951.
21-Jun-2024 09:12:31 bconsole: watchdog.c:217-0 Unregistered watchdog 55cbc59c3c48
21-Jun-2024 09:12:31 bconsole: watchdog.c:303-0 NicB-reworked watchdog thread exited
21-Jun-2024 09:12:31 bconsole: parse_conf.c:1829-0 i=1001, next=0
21-Jun-2024 09:12:31 bconsole: parse_conf.c:1829-0 i=1002, next=55cbc59a1668
21-Jun-2024 09:12:31 bconsole: lockmgr.c:792-0 Exit check_deadlock.
real 15.24
user 0.05
sys 0.01
And, you can find next the result of bacula-dir.state when i used the previous command :
director-dir: bsock.c:860-0 socket=5 who=client host=MY_WEBSERVER_PUBLIC_IP port=MY_WEBSERVER_PORT
328 director-dir: bnet_server.c:235-0 Accept socket=MY_WEBSERVER_PUBLIC_IP.MY_WEBSERVER_PORT:MY_WEBSERVER_PUBLIC_IP.43198 s=0x7fcd1400b508
329 director-dir: jcr.c:1011-0 set_jcr_job_status(0, C)
330 director-dir: jcr.c:981-0 OnEntry JobStatus=0 newJobstatus=C
331 director-dir: jcr.c:991-0 Set new stat. old: 0,0 new: C,0
332 director-dir: jcr.c:997-0 leave setJobStatus old=0 new=C
333 director-dir: job.c:1781-0 Setting ListedOrder storage group policy for JobId: 0
334 director-dir: job.c:1827-0 Using Storage definition from the Pool resource for JobId: 0
335 director-dir: message.c:392-0 Copy message resource 5599d2a42978 to 7fccf00380d8
336 director-dir: job.c:1633-0 JobId=0 created Job=-Console-.2024-06-21_09.35.55_00
337 director-dir: jcr.c:1011-0 set_jcr_job_status(0, R)
338 director-dir: jcr.c:981-0 OnEntry JobStatus=C newJobstatus=R
339 director-dir: jcr.c:991-0 Set new stat. old: C,0 new: R,0
340 director-dir: jcr.c:997-0 leave setJobStatus old=C new=R
341 director-dir: dir_plugins.c:234-0 === enter new_plugins ===
342 director-dir: dir_plugins.c:236-0 No Director plugin list!
343 director-dir: authenticate.c:283-0 authenticate user agent: Hello *UserAgent* calling 200 tlspsk=202
344 director-dir: authenticatebase.cc:339-0 TLSPSK Local need 202
345 director-dir: authenticatebase.cc:371-0 TLSPSK Remote need 202
346 director-dir: authenticatebase.cc:582-0 TLSPSK Start TLS
347 director-dir: bnet.c:96-0 TLS server negotiation established.
348 director-dir: cram-md5.c:68-0 send: auth cram-md5 challenge <1321197997.1718955355@director-dir> ssl=2
349 director-dir: cram-md5.c:132-0 cram-get received: auth cram-md5 <1489389675.1718955355@bconsole> ssl=2
350 director-dir: cram-md5.c:156-0 sending resp to challenge: YhliR1tDWx+nD75JoilYnC
351 director-dir: mem_pool.c:616-0 max_size=512
352 director-dir: events.c:48-0 Events: code=DC0015 daemon=director-dir ref=0x7fccf00273a8 type=connection source=*Console* text=Connection from MY_WEBSERVER_PUBLIC_IP:MY_WEBSERVER_PORT
353 director-dir: message.c:1534-0 Enter Jmsg type=3
354 director-dir: message.c:818-0 Enter dispatch_msg type=3 msg=Events: code=DC0015 daemon=director-dir ref=0x7fccf00273a8 type=connection source=*Console* text=Connection from MY_WEBSERVER_PUBLIC_IP:MY_WEBSERVER_PORT
355 director-dir: dird.c:107-0 Open Catalog for message
356 director-dir: sql.c:113-0 int_handler starts with row pointing at f0027dd8
357 director-dir: sql.c:116-0 int_handler finds '1026'
358 director-dir: sql.c:122-0 int_handler finishes
359 director-dir: sql.c:113-0 int_handler starts with row pointing at f0027dd8
360 director-dir: sql.c:116-0 int_handler finds '1026'
361 director-dir: sql.c:122-0 int_handler finishes
362 director-dir: scan.c:171-0 Next arg=gui on
363 director-dir: scan.c:195-0 End arg=gui next=on
364 director-dir: scan.c:171-0 Next arg=on
365 director-dir: scan.c:195-0 End arg=on next=
366 director-dir: scan.c:171-0 Next arg=
367 director-dir: scan.c:195-0 End arg= next=
368 director-dir: ua_cmds.c:277-0 Command: gui
369 director-dir: scan.c:171-0 Next arg=.jobs
370 director-dir: scan.c:195-0 End arg=.jobs next=
371 director-dir: scan.c:171-0 Next arg=
372 director-dir: scan.c:195-0 End arg= next=
373 director-dir: ua_dotcmds.c:203-0 Cmd: .jobs
374 director-dir: scan.c:171-0 Next arg=quit
375 director-dir: scan.c:195-0 End arg=quit next=
376 director-dir: scan.c:171-0 Next arg=
377 director-dir: scan.c:195-0 End arg= next=
378 director-dir: ua_cmds.c:277-0 Command: quit
379 director-dir: mem_pool.c:616-0 max_size=512
380 director-dir: events.c:48-0 Events: code=DC0016 daemon=director-dir ref=0x7fccf00273a8 type=connection source=*Console* text=Disconnection from MY_WEBSERVER_PUBLIC_IP:MY_WEBSERVER_PORT
381 director-dir: message.c:1534-0 Enter Jmsg type=3
382 director-dir: message.c:818-0 Enter dispatch_msg type=3 msg=Events: code=DC0016 daemon=director-dir ref=0x7fccf00273a8 type=connection source=*Console* text=Disconnection from MY_WEBSERVER_PUBLIC_IP:MY_WEBSERVER_PORT
383 director-dir: dird.c:107-0 Open Catalog for message
384 director-dir: sql.c:113-0 int_handler starts with row pointing at f0029928
385 director-dir: sql.c:116-0 int_handler finds '1026'
386 director-dir: sql.c:122-0 int_handler finishes
387 director-dir: sql.c:113-0 int_handler starts with row pointing at f0029928
388 director-dir: sql.c:116-0 int_handler finds '1026'
389 director-dir: sql.c:122-0 int_handler finishes
390 director-dir: bsockcore.c:1123-0 BSOCKCORE::destroy()
391 director-dir: bsockcore.c:1136-0 BSOCKCORE::destroy():delete(this)
392 director-dir: bsock.c:90-0 BSOCK::~BSOCK()
393 director-dir: bsock.c:110-0 BSOCK::_destroy()
394 director-dir: bsockcore.c:201-0 BSOCKCORE::~BSOCKCORE()
395 director-dir: bsockcore.c:1090-0 BSOCKCORE::_destroy()
396 director-dir: bsockcore.c:1052-0 BSOCKCORE::close()
397 director-dir: watchdog.c:196-0 Registered watchdog 7fccf002e748, interval 120 one shot
398 director-dir: btimers.c:176-0 Start bsock timer 7fccf000c448 tid=7fcd1a7fc700 for 120 secs at 1718955355
399 director-dir: btimers.c:212-0 Stop bsock timer 7fccf000c448 tid=7fcd1a7fc700 at 1718955355.
400 director-dir: watchdog.c:217-0 Unregistered watchdog 7fccf002e748
401 director-dir: watchdog.c:196-0 Registered watchdog 7fccf002e748, interval 120 one shot
402 director-dir: btimers.c:176-0 Start bsock timer 7fccf000c448 tid=7fcd1a7fc700 for 120 secs at 1718955355
403 director-dir: btimers.c:212-0 Stop bsock timer 7fccf000c448 tid=7fcd1a7fc700 at 1718955355.
404 director-dir: watchdog.c:217-0 Unregistered watchdog 7fccf002e748
405 director-dir: message.c:562-0 Close_msg jcr=7fccf002fa28
406 director-dir: message.c:587-0 ===Begin close msg resource at 7fccf003ae68
407 director-dir: message.c:676-0 Done walking message chain.
408 director-dir: message.c:683-0 ===End close msg resource
409 director-dir: job.c:1679-0 Start dird free_jcr
410 director-dir: mem_pool.c:372-0 garbage collect memory pool
411 director-dir: job.c:1730-0 End dird free_jcr
412 director-dir: message.c:562-0 Close_msg jcr=0
413 director-dir: message.c:587-0 ===Begin close msg resource at 5599d29feef8
414 director-dir: message.c:676-0 Done walking message chain.
415 director-dir: message.c:683-0 ===End close msg resource
Thanks for your time,
Kind,
Romain
Romain Delmas
Jun 21, 2024, 4:46:18 AM6/21/24
to bacularis
Hello,
The delay seems to be specifically linked to the initialisation and expiry of the 15-second timer configured by the watchdog, but on my unit file i don't have WatchdogSec conf...
Sincerly,
Romain
Marcin Haba
Jun 21, 2024, 8:59:54 PM6/21/24
to Romain Delmas, bacularis
Hello Romain,
Thanks for providing this debug output.
For me it looks that this connection times out when bconsole is trying to connect to the Director. Could you tell me if in this /opt/bacula/etc/bconsole.conf file you use in the Address directive an IP address or a name? If it is the name, could you do a try with changing the name into the Director IP address? I mean to do it only for tests.
Once you change it, could you please check if Bacularis started working well or it still slows down?
Thanks for providing this debug output.
For me it looks that this connection times out when bconsole is trying to connect to the Director. Could you tell me if in this /opt/bacula/etc/bconsole.conf file you use in the Address directive an IP address or a name? If it is the name, could you do a try with changing the name into the Director IP address? I mean to do it only for tests.
Once you change it, could you please check if Bacularis started working well or it still slows down?
Best regards,
Marcin Haba (gani)
To view this discussion on the web, visit https://groups.google.com/d/msgid/bacularis/fd5e210e-cad3-40d9-b6e5-644971bb4a96n%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
Romain Delmas
Jun 23, 2024, 9:41:19 AM6/23/24
to bacularis
Hi,
23-Jun-2024 15:24:08 bconsole: tls.c:644-0 No subject name match. Host=IP.IP.IP.IP cert=MY_WEBSERVER_FQDN
Director authorization problem.
I tried to change the Address directive with localhost/LAN IP/Public IP, but modifying this part will cause the certificate verification to fail...
23-Jun-2024 15:24:08 bconsole: tls.c:644-0 No subject name match. Host=IP.IP.IP.IP cert=MY_WEBSERVER_FQDN
Director authorization problem.
On an other hand, it's possible to find a link: I've modified my hosts file and I've gained 5sc (10sc instead of 15sc)...
Maybe should i modify the certificate/key to include a CN linked to the IP...
Kind to you,
Romain
Marcin Haba
Jun 23, 2024, 1:00:28 PM6/23/24
to Romain Delmas, bacularis
On Sun, 23 Jun 2024 at 15:41, Romain Delmas <romain...@5group.fr> wrote:
Hi,
I tried to change the Address directive with localhost/LAN IP/Public IP, but modifying this part will cause the certificate verification to fail...
23-Jun-2024 15:24:08 bconsole: tls.c:644-0 No subject name match. Host=IP.IP.IP.IP cert=MY_WEBSERVER_FQDN
Director authorization problem.On an other hand, it's possible to find a link: I've modified my hosts file and I've gained 5sc (10sc instead of 15sc)...
Hello Romain,
I think we are on a good track to solving it.
I think we are on a good track to solving it.
Maybe should i modify the certificate/key to include a CN linked to the IP...
Yes, you can try. However, if after this change it will start working, the real problem will not be solved anyway, but at least we will be sure that it is a DNS specific problem with converting names into IP addresses.
Additionally if you want, you can do a test how much time takes on the host with bconsole translating name into address by running the "host" command (if installed):
time -p host MY_WEBSERVER_FQDN
Additionally if you want, you can do a test how much time takes on the host with bconsole translating name into address by running the "host" command (if installed):
time -p host MY_WEBSERVER_FQDN
Best regards,
Marcin Haba (gani)
Romain Delmas
Jun 23, 2024, 2:02:06 PM6/23/24
to bacularis
Hi again,
i tried the command :
:~$ time -p host MY_WEBSERVER_FQDN
my_webserver_fqdn has address PUBLIC_IP
real 3.25
user 0.00
sys 0.01
my_webserver_fqdn has address PUBLIC_IP
real 3.25
user 0.00
sys 0.01
In fact, it's quite strange, the server doesn't give priority to local name resolution... I checked, and the /etc/nsswitch.conf file well incorporates the line : "hosts: files dns"
it's very long, 3.25s... on my other servers I'm around 0.1/0.3s
I'm looking on that...
Thnaks again,
i'm going to solve the problem rather than diverting it -_-'
Best regards,
Romain
Romain Delmas
Jun 24, 2024, 2:22:47 AM6/24/24
to bacularis
Good morning,
Hum, there's a problem with local resolution, i guess :
:~$ time getent hosts MY_WEBSERVER_FQDN
IP.IP.IP.IP MY_WEBSERVER_FQDN
real 0m10.028s
user 0m0.002s
sys 0m0.000s
IP.IP.IP.IP MY_WEBSERVER_FQDN
real 0m10.028s
user 0m0.002s
sys 0m0.000s
i'm looking that way.
Best regards,
Romain Delmas
Jun 24, 2024, 2:48:08 AM6/24/24
to bacularis
Hi Marcin,
i found... i had an old DNS IP resolver on my resolv.conf...
All I had to do was remove it and everything was back in place and ready to serve...
Very thanks to you !
Best regards,
Romain
Marcin Haba
Jun 24, 2024, 2:53:53 AM6/24/24
to Romain Delmas, bacularis
Hi Romain,
Great to hear :-) You hit the jackpot.
Thanks for letting us know.
Great to hear :-) You hit the jackpot.
Thanks for letting us know.
Best regards,
Marcin Haba (gani)
--
You received this message because you are subscribed to the Google Groups "bacularis" group.
To unsubscribe from this group and stop receiving emails from it, send an email to bacularis+...@googlegroups.com.
To view this discussion on the web, visit https://groups.google.com/d/msgid/bacularis/097fda35-9391-4f6d-b05b-fe072e5dce74n%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
Reply all
Reply to author
Forward
0 new messages