• Willkommen im Linux Club - dem deutschsprachigen Supportforum für GNU/Linux. Registriere dich kostenlos, um alle Inhalte zu sehen und Fragen zu stellen.

bacula: Fatal error: Bad response to Storage command: wanted 2000 OK storage , got 2800 End Job TermCode=102

gehrke

gehrke

Administrator
Teammitglied
Moin *

Mehrere Clients auf Basis von Fedora werden plötzlich nicht mehr durch Bacula gesichert.

Serverseitiges Log:
Code: 
25-Apr 09:45 bacula-dir JobId 3773: Created new Volume="inc-j10-2.2021-04-25_09.45.05_16-3773-108", Pool="j10-2-inc", MediaType="File2" in catalog.
25-Apr 09:45 bacula-dir JobId 3773: Using Device "disk2-j10" to write.
25-Apr 09:45 bacula-dir JobId 3773: Error: getmsg.c:209 Malformed message: Events: code=FC0002 daemon=j10-fd ref=0x7f086400b328 type=connection source=bacula-dir text=Director connection

25-Apr 09:45 j10-fd JobId 3773: Fatal error: hello.c:191 Bad caps from SD: auth cram-md5 <1220413786.1619336706@bacula-sd> ssl=0
.
25-Apr 09:45 bacula-dir JobId 3773: Fatal error: Bad response to Storage command: wanted 2000 OK storage
, got 2800 End Job TermCode=102 JobFiles=0 ReadBytes=0 JobBytes=0 Errors=1 VSS=0 Encrypt=0 CommBytes=64 CompressCommBytes=64

25-Apr 09:45 bacula-dir JobId 3773: Fatal error: No Job status returned from FD.
25-Apr 09:45 bacula-dir JobId 3773: Error: Bacula bacula-dir 9.0.6 (20Nov17):
  Build OS:               x86_64-redhat-linux-gnu redhat (Core)
  JobId:                  3773
  Job:                    j10-2.2021-04-25_09.45.05_16
  Backup Level:           Incremental, since=2021-04-24 09:42:07
  Client:                 "j10-fd" 11.0.2 (26Mar21) x86_64-redhat-linux-gnu,redhat,Three)
  FileSet:                "full linux client - by FS-Type" 2020-08-10 09:37:53
  Pool:                   "j10-2-inc" (From Job IncPool override)
  Catalog:                "MyCatalog" (From Client resource)
  Storage:                "File2-j10" (From Pool resource)
  Scheduled time:         25-Apr-2021 09:45:05
  Start time:             25-Apr-2021 09:45:05
  End time:               25-Apr-2021 09:45:06
  Elapsed time:           1 sec
  Priority:               10
  FD Files Written:       0
  SD Files Written:       0
  FD Bytes Written:       0 (0 B)
  SD Bytes Written:       0 (0 B)
  Rate:                   0.0 KB/s
  Software Compression:   None
  Comm Line Compression:  None
  Snapshot/VSS:           no
  Encryption:             no
  Accurate:               no
  Volume name(s):         
  Volume Session Id:      3928
  Volume Session Time:    1617295640
  Last Volume Bytes:      0 (0 B)
  Non-fatal FD errors:    1
  SD Errors:              0
  FD termination status:  Error
  SD termination status:  Waiting on FD
  Termination:            *** Backup Error ***

25-Apr 09:45 bacula-dir JobId 3773: Rescheduled Job j10-2.2021-04-25_09.45.05_16 at 25-Apr-2021 09:45 to re-run in 3600 seconds (25-Apr-2021 10:45).
25-Apr 09:45 bacula-dir JobId 3773: Job j10-2.2021-04-25_09.45.05_16 waiting 3600 seconds for scheduled start time.
25-Apr 10:45 bacula-dir JobId 3773: Start Backup JobId 3773, Job=j10-2.2021-04-25_09.45.05_16
25-Apr 10:45 bacula-dir JobId 3773: Using Device "disk2-j10" to write.
25-Apr 10:45 bacula-dir JobId 3773: Warning: bsock.c:141 Could not connect to Client: j10-fd on j10-wlan:9102. ERR=Keine Route zum Zielrechner
Status des Clients:
Code: 
● bacula-fd.service - Bacula File Daemon
     Loaded: loaded (/usr/lib/systemd/system/bacula-fd.service; enabled; vendor preset: disabled)
     Active: active (running) since Mon 2021-04-26 11:56:11 CEST; 1 weeks 3 days ago
       Docs: man:bacula-fd(8)
   Main PID: 117188 (bacula-fd)
      Tasks: 3 (limit: 9380)
     Memory: 1.7M
        CPU: 359ms
     CGroup: /system.slice/bacula-fd.service
             └─117188 /usr/sbin/bacula-fd -f -c /etc/bacula/bacula-fd.conf -u root -g root

Mai 04 06:37:08 j10.gehrke.local bacula-fd[117188]: j10-fd: hello.c:191-3889 Bad caps from SD: auth cram-md5 <1847218702.1620103029@bacula-sd> ssl=0
Mai 04 06:37:08 j10.gehrke.local bacula-fd[117188]: .
Mai 05 21:19:16 j10.gehrke.local bacula-fd[117188]: j10-fd: hello.c:191-3921 Bad caps from SD: auth cram-md5 <248210867.1620242356@bacula-sd> ssl=0
Mai 05 21:19:16 j10.gehrke.local bacula-fd[117188]: .
Mai 06 07:47:26 j10.gehrke.local bacula-fd[117188]: j10-fd: hello.c:191-3921 Bad caps from SD: auth cram-md5 <850501153.1620280046@bacula-sd> ssl=0
Mai 06 07:47:26 j10.gehrke.local bacula-fd[117188]: .
Mai 06 16:03:49 j10.gehrke.local bacula-fd[117188]: j10-fd: hello.c:191-3937 Bad caps from SD: auth cram-md5 <530996766.1620309829@bacula-sd> ssl=0
Mai 06 16:03:49 j10.gehrke.local bacula-fd[117188]: .
Mai 06 19:10:10 j10.gehrke.local bacula-fd[117188]: j10-fd: hello.c:191-3937 Bad caps from SD: auth cram-md5 <471440642.1620321010@bacula-sd> ssl=0
Mai 06 19:10:10 j10.gehrke.local bacula-fd[117188]: .
Zuvor lief das jahrelang problemlos und Konfigurationsänderungen sind mir nicht bekannt.

Das fällt zeitlich frapierend zusammen mit einem Systemupgrade:
Code: 
# dnf history info 620
Transaktions-ID : 620
Anfangszeit : So 25 Apr 2021 09:44:50 CEST
Anfang rpmdb    : 2935:8062501e559f7fa62f245cd2dfae0729d916d470
Endzeit : So 25 Apr 2021 09:45:04 CEST (14 Sekunden)
Ende rpmdb      : 2935:3069174b9216528fe2a02a6eaef4dc04cf014ee5
Benutzer : System <nicht gesetzt>
Rückgabe-Code    : Erfolg
Releasever: 33
Befehlszeile   : 
Kommentar        : 
Veränderte Pakete:
    Upgrade  bacula-client-11.0.2-3.fc33.x86_64                   @updates
    Upgraded bacula-client-9.6.7-1.fc33.x86_64                    @@System
    Upgrade  bacula-common-11.0.2-3.fc33.x86_64                   @updates
    Upgraded bacula-common-9.6.7-1.fc33.x86_64                    @@System
    Upgrade  bacula-libs-11.0.2-3.fc33.x86_64                     @updates
    Upgraded bacula-libs-9.6.7-1.fc33.x86_64                      @@System
Eine Recherche zeigt lediglich wenig hilfreiche Einträge von vor 2016. Scheint etwas neues zu sein.

Glückauf, gehrke
 
OP
gehrke

gehrke

Administrator
Teammitglied
Ich versuche es mal mit einer älteren clientseitigen Version:
Code: 
# dnf downgrade bacula-client
Letzte Prüfung auf abgelaufene Metadaten: vor 3:18:37 am Do 06 Mai 2021 18:52:41 CEST.
Abhängigkeiten sind aufgelöst.
========================================================================================================================================================
 Package                                 Architecture                     Version                                Repository                        Size
========================================================================================================================================================
Herunterstufen:
 bacula-client                           x86_64                           9.6.5-2.fc33                           fedora                           144 k
 bacula-common                           x86_64                           9.6.5-2.fc33                           fedora                            18 k
 bacula-libs                             x86_64                           9.6.5-2.fc33                           fedora                           543 k

Transaktionsübersicht
========================================================================================================================================================
Zurücksetzen  3 Pakete

Gesamte Downloadgröße: 705 k
Ist dies in Ordnung? [j/N]: j
Pakete werden heruntergeladen:
(1/3): bacula-common-9.6.5-2.fc33.x86_64.rpm                                                                            154 kB/s |  18 kB     00:00    
(2/3): bacula-client-9.6.5-2.fc33.x86_64.rpm                                                                            507 kB/s | 144 kB     00:00    
(3/3): bacula-libs-9.6.5-2.fc33.x86_64.rpm                                                                              1.2 MB/s | 543 kB     00:00    
--------------------------------------------------------------------------------------------------------------------------------------------------------
Gesamt                                                                                                                  826 kB/s | 705 kB     00:00     
Transaktionsüberprüfung wird ausgeführt
Transaktionsprüfung war erfolgreich.
Transaktion wird getestet
Transaktionstest war erfolgreich.
Transaktion wird ausgeführt
  Vorbereitung läuft    :                                                                                                                           1/1 
  Ausgeführtes Scriptlet: bacula-libs-9.6.5-2.fc33.x86_64                                                                                           1/1 
  Downgrading           : bacula-libs-9.6.5-2.fc33.x86_64                                                                                           1/6 
  Ausgeführtes Scriptlet: bacula-common-9.6.5-2.fc33.x86_64                                                                                         2/6 
  Downgrading           : bacula-common-9.6.5-2.fc33.x86_64                                                                                         2/6 
  Downgrading           : bacula-client-9.6.5-2.fc33.x86_64                                                                                         3/6 
Warnung: /etc/bacula/bacula-fd.conf erstellt als /etc/bacula/bacula-fd.conf.rpmnew

  Ausgeführtes Scriptlet: bacula-client-9.6.5-2.fc33.x86_64                                                                                         3/6 
  Ausgeführtes Scriptlet: bacula-client-11.0.2-3.fc33.x86_64                                                                                        4/6 
  Aufräumen             : bacula-client-11.0.2-3.fc33.x86_64                                                                                        4/6 
  Ausgeführtes Scriptlet: bacula-client-11.0.2-3.fc33.x86_64                                                                                        4/6 
  Aufräumen             : bacula-common-11.0.2-3.fc33.x86_64                                                                                        5/6 
  Aufräumen             : bacula-libs-11.0.2-3.fc33.x86_64                                                                                          6/6 
  Ausgeführtes Scriptlet: bacula-libs-11.0.2-3.fc33.x86_64                                                                                          6/6 
  Überprüfung läuft     : bacula-client-9.6.5-2.fc33.x86_64                                                                                         1/6 
  Überprüfung läuft     : bacula-client-11.0.2-3.fc33.x86_64                                                                                        2/6 
  Überprüfung läuft     : bacula-common-9.6.5-2.fc33.x86_64                                                                                         3/6 
  Überprüfung läuft     : bacula-common-11.0.2-3.fc33.x86_64                                                                                        4/6 
  Überprüfung läuft     : bacula-libs-9.6.5-2.fc33.x86_64                                                                                           5/6 
  Überprüfung läuft     : bacula-libs-11.0.2-3.fc33.x86_64                                                                                          6/6 

Zurückgesetzt:
  bacula-client-9.6.5-2.fc33.x86_64                  bacula-common-9.6.5-2.fc33.x86_64                  bacula-libs-9.6.5-2.fc33.x86_64                 

Fertig.
Und ja, sieht gut aus. Die ersten 223 MB werden soeben gesichert. Ich gehe davon aus, dass das erfolgreich durchläuft.

Aber das ist natürlich nur ein erstes Indiz, dass die neue Version buggy ist oder mit der serverseitigen Version nicht kompatibel ist.
 
OP
gehrke

gehrke

Administrator
Teammitglied
Ach so, wenn schon Workaround, dann wenigstens fix:
Code: 
# dnf versionlock add bacula-client-9.6.5-2.fc33.x86_64 bacula-common-9.6.5-2.fc33.x86_64 bacula-libs-9.6.5-2.fc33.x86_64
Letzte Prüfung auf abgelaufene Metadaten: vor 3:38:03 am Do 06 Mai 2021 18:52:41 CEST.
Versionssperre wird hinzugefügt zu: bacula-libs-0:9.6.5-2.fc33.*
Versionssperre wird hinzugefügt zu: bacula-client-0:9.6.5-2.fc33.*
Versionssperre wird hinzugefügt zu: bacula-common-0:9.6.5-2.fc33.*
 
OP
gehrke

gehrke

Administrator
Teammitglied
Der obige Workaround funktioniert hässlich, aber stabil für die Clients mit Fedora 33.

Einer meiner Clients ist aber schon frisch auf Fedora 34. Auch dort scheitert das Backup:
Code: 
08-Mai 13:27 j12-fd JobId 3983: Fatal error: hello.c:191 Bad caps from SD: auth cram-md5 <1882231691.1620473249@bacula-sd> ssl=0
.
08-Mai 13:27 bacula-dir JobId 3983: Fatal error: Bad response to Storage command: wanted 2000 OK storage
, got 2800 End Job TermCode=102 JobFiles=0 ReadBytes=0 JobBytes=0 Errors=1 VSS=0 Encrypt=0 CommBytes=64 CompressCommBytes=64

08-Mai 13:27 bacula-dir JobId 3983: Fatal error: No Job status returned from FD.

08-Mai 13:28 bacula-dir JobId 0: Error: getmsg.c:209 Malformed message: Events: code=FC0002 daemon=j12-fd ref=0x7f8b2400b098 type=connection source=bacula-dir text=Director connection

Code: 
[root@j12 ~]# systemctl status bacula-fd.service 
● bacula-fd.service - Bacula File Daemon
     Loaded: loaded (/usr/lib/systemd/system/bacula-fd.service; enabled; vendor preset: disabled)
     Active: active (running) since Sat 2021-05-08 12:01:43 CEST; 1h 19min ago
       Docs: man:bacula-fd(8)
   Main PID: 1420 (bacula-fd)
      Tasks: 3 (limit: 9111)
     Memory: 3.0M
        CPU: 36ms
     CGroup: /system.slice/bacula-fd.service
             └─1420 /usr/sbin/bacula-fd -f -c /etc/bacula/bacula-fd.conf -u root -g root

Mai 08 12:01:43 j12 systemd[1]: Started Bacula File Daemon.
Mai 08 13:13:30 j12 bacula-fd[1420]: job.c:548 FD expecting Hello got bad command from 172.16.21.11. Len=-4.
Mai 08 13:14:03 j12 bacula-fd[1420]: j12-fd: hello.c:191-3982 Bad caps from SD: auth cram-md5 <1823788466.1620472443@bacula-sd> ssl=0
Mai 08 13:14:03 j12 bacula-fd[1420]: .
Mai 08 13:18:38 j12 bacula-fd[1420]: job.c:548 FD expecting Hello got bad command from 172.16.21.11. Len=-720899.

Code: 
[root@j12 ~]# dnf info bacula-client
Installierte Pakete
Name         : bacula-client
Version      : 11.0.2
Release      : 3.fc34
Architecture : x86_64
Size         : 591 k
Quelle       : bacula-11.0.2-3.fc34.src.rpm
Repository   : @System
Aus Paketque : updates
Summary      : Bacula backup client
URL          : http://www.bacula.org
Lizenz       : AGPLv3 with exceptions
Description  : Bacula is a set of programs that allow you to manage the backup, recovery, and
             : verification of computer data across a network of different computers. It is
             : based on a client/server architecture.
             : 
             : This package contains the bacula client, the daemon running on the system to be
             : backed up.
Ein Downgrade führt hier zu einer nur marginal veränderten Version, die das selbe Verhalten zeigt:
Code: 
(1/3): bacula-common-11.0.1-1.fc34.x86_64.rpm                                                            260 kB/s |  18 kB     00:00    
(2/3): bacula-client-11.0.1-1.fc34.x86_64.rpm                                                            1.5 MB/s | 227 kB     00:00    
(3/3): bacula-libs-11.0.1-1.fc34.x86_64.rpm                                                              2.5 MB/s | 593 kB     00:00    
-----------------------------------------------------------------------------------------------------------------------------------------
Gesamt                                                                                                   2.3 MB/s | 838 kB     00:00
 
S

spoensche

Neue Client Version, alte Fd Version bzw. alte Director Version, richtig?

Zwischen Version 9 und 11 ist der Unterschied nicht gerade gering. Unterschiedliche Protokollversionen können z.B. zu diesem Problem führen.
 
OP
gehrke

gehrke

Administrator
Teammitglied
Ja, es ist der Spagat der Versionen. Aber damit muss Bacula klarkommen, so war es immer schon und so ist es auch dokumentiert. Denn sonst gibt es in so heterogenen Umgebungen wie meiner sehr schnell Probleme. Da gibt es hochaktuelle Clients mit Fedora 34 neben Debian 9 und CentOS 7.
Bislang war das kein Problem.
 
OP
gehrke

gehrke

Administrator
Teammitglied
Ich habe das leider aus dem Auge verloren bzw. habe bei der Lösungsfindung verkackt. Und ich hatte die Upgrades der anderen Clients hinausgezögert, die noch auf Fedora 33 waren. Im Dezember ist aber dort der Support ausgelaufen und ich geriet unter Zugzwang.

Mittlerweile sind alle Clients auf Fedora 35 und wie zu erwarten, lief nirgendwo die mitgelieferte Release 11 von bacula-fd.

Ich rette mich aktuell mit diesem hässlichen Workaround:
Code: 
# dnf install https://rpmfind.net/linux/fedora/linux/releases/33/Everything/x86_64/os/Packages/b/bacula-libs-9.6.5-2.fc33.x86_64.rpm https://rpmfind.net/linux/fedora/linux/releases/33/Everything/x86_64/os/Packages/b/bacula-common-9.6.5-2.fc33.x86_64.rpm https://rpmfind.net/linux/fedora/linux/releases/33/Everything/x86_64/os/Packages/b/bacula-client-9.6.5-2.fc33.x86_64.rpm
Der Client von Fedora 33 läuft auch auf 34 und 35 noch.

Ja, ich weiß, dass man dafür in die Hölle kommt und dass das mit Fedora 36 in wenigen Monaten explodieren kann - oder früher. Aber bislang bin ich bei allen Lösungsansätzen gescheitert.

Bin aber fast sicher, dass das kein Bug ist. Es hat irgendwas mit in Release 11 defaultmässiger TLS-Transportwegverschlüsselung zu tun, von der ich bislang in internen LAN abgesehen habe. Aber das PKI-Zeugs unter Bacula ist auch nicht trivial. :zensur:
 
OP
gehrke

gehrke

Administrator
Teammitglied
Ich finde ja, wenn man schon pfuscht, dann auch richtig. ;-)

Mittlerweile sind wir bei Fedora 36 und der Workaround funktioniert immer noch. Aber die oben genannten RPMs wurden vom Server entfernt, was bei Neu-Installationen hinderlich ist.

Ich bin hier alternativ fündig geworden und habe diesmal lokal gespeichert:
ftp.pbone.net/vol4/archive.fedoraproject.org/fedora/linux/releases/33/Everything/x86_64/os/Packages/b/bacula-*-9.6.5-2.fc33.x86_64.rpm

Mangels Original-RPMs konnte ich zwar kein Diff der Pakete machen, aber zumindest ein Vergleich der Hashwerte (sha256sum) der installierten Binaries stimmte mit einem Referenzsystem überein.
 
OP
gehrke

gehrke

Administrator
Teammitglied
Ein weiteres Dist-Upgrade später darf ich vermelden, dass dieser fiese kleine Pfusch auch weiterhin mit Fedora 37 hervorragend funktioniert.
 
Du musst dich einloggen oder registrieren, um hier zu antworten.
Oben