Re: Something amiss in bacula-9.6.7: Possible race condition

On 1/15/21 5:50 PM, Phil Stracchino wrote:
> On 1/15/21 2:18 PM, Phil Stracchino wrote:
>> If we INSERT IGNORE and there IS an existing matching record, then the
>> record is NOT inserted, no error is thrown, but mysql_affected_rows()
>> and mysql_insert_id() both return 0, and so does
>> sql_insert_autokey_record().
> 
> 
> Footnote I omitted:  while my patch shouldn't break anything, it won't
> work on its own *anyway* because sql_insert_autokey_record() will still
> fail.

And I only had to wait a single day to see confirmation of this.  Four
jobs completed successfully, one with a fatal error on a duplicate entry
into Filename but did not terminate, last job (DB backup) stalled
waiting on the fifth to complete.



16-Jan 04:30 minbar-dir JobId 28499: shell command: run BeforeJob
"/etc/bacula/checkhost asgard"
16-Jan 04:30 minbar-dir JobId 28505: shell command: run BeforeJob
"/etc/bacula/checkhost babylon5"
16-Jan 04:30 minbar-dir JobId 28502: shell command: run BeforeJob
"/etc/bacula/checkhost asgard"
16-Jan 04:30 minbar-dir JobId 28499: Start Backup JobId 28499,
Job=Asgard_Backup.2021-01-16_04.30.00_02
16-Jan 04:30 minbar-dir JobId 28502: Start Backup JobId 28502,
Job=Netstore_Backup.2021-01-16_04.30.00_03
16-Jan 04:30 minbar-dir JobId 28505: Start Backup JobId 28505,
Job=Babylon5_Backup.2021-01-16_04.30.00_04
16-Jan 04:30 minbar-dir JobId 28499: Max configured use duration=82,800
sec. exceeded. Marking Volume "INCR-20210115-04:30" as Used.
16-Jan 04:30 minbar-dir JobId 28508: shell command: run BeforeJob
"/etc/bacula/checkhost minbar"
16-Jan 04:30 minbar-dir JobId 28511: shell command: run BeforeJob
"/etc/bacula/checkhost narn"
16-Jan 04:30 minbar-dir JobId 28511: Start Backup JobId 28511,
Job=Narn_Backup.2021-01-16_04.30.00_06
16-Jan 04:30 minbar-dir JobId 28508: Start Backup JobId 28508,
Job=Minbar_Backup.2021-01-16_04.30.00_05
16-Jan 04:30 minbar-dir JobId 28499: There are no more Jobs associated
with Volume "DIFF-20201116-04:30". Marking it purged.
16-Jan 04:30 minbar-dir JobId 28499: New Pool is: Scratch
16-Jan 04:30 minbar-dir JobId 28499: All records pruned from Volume
"DIFF-20201116-04:30"; marking it "Purged"
16-Jan 04:31 minbar-dir JobId 28499: There are no more Jobs associated
with Volume "INCR-20201216-04:30". Marking it purged.
16-Jan 04:31 minbar-dir JobId 28499: New Pool is: Scratch
16-Jan 04:31 minbar-dir JobId 28499: All records pruned from Volume
"INCR-20201216-04:30"; marking it "Purged"
16-Jan 04:31 minbar-dir JobId 28499: Created new
Volume="INCR-20210116-04:31", Pool="Incr-Disk", MediaType="File" in catalog.
16-Jan 04:31 minbar-dir JobId 28499: Using Device "FileStorage" to write.
16-Jan 04:31 minbar-dir JobId 28502: Using Device "FileStorage" to write.
16-Jan 04:31 minbar-dir JobId 28505: Using Device "FileStorage" to write.
16-Jan 04:31 minbar-dir JobId 28511: Using Device "FileStorage" to write.
16-Jan 04:31 minbar-dir JobId 28508: Using Device "FileStorage" to write.
16-Jan 04:31 asgard-sd JobId 28508: Labeled new Volume
"INCR-20210116-04:31" on File device "FileStorage" (/spool/bacula).
16-Jan 04:31 asgard-sd JobId 28508: Wrote label to prelabeled Volume
"INCR-20210116-04:31" on File device "FileStorage" (/spool/bacula)
16-Jan 04:31 asgard-fd JobId 28499:      /var is a different filesystem.
Will not descend from / into it.
16-Jan 04:31 asgard-fd JobId 28499:      /replicas is a different
filesystem. Will not descend from / into it.
16-Jan 04:31 asgard-fd JobId 28499:      /dev is a different filesystem.
Will not descend from / into it.
16-Jan 04:31 asgard-fd JobId 28499:      /arcpool is a different
filesystem. Will not descend from / into it.
16-Jan 04:31 asgard-fd JobId 28499:      /netstore is a different
filesystem. Will not descend from / into it.
16-Jan 04:31 babylon5-fd JobId 28505:      /home/alaric/.data is a
different filesystem. Will not descend from / into it.
16-Jan 04:31 minbar-fd JobId 28508:      /home/ftp is a different
filesystem. Will not descend from / into it.
16-Jan 04:31 minbar-fd JobId 28508:      /netstore is a different
filesystem. Will not descend from / into it.
16-Jan 04:31 minbar-fd JobId 28508:      /proc is a different
filesystem. Will not descend from / into it.
16-Jan 04:31 narn-fd JobId 28511:      /netstore is a different
filesystem. Will not descend from / into it.
16-Jan 04:31 narn-fd JobId 28511:      /proc is a different filesystem.
Will not descend from / into it.
16-Jan 04:31 narn-fd JobId 28511:      /run is a different filesystem.
Will not descend from / into it.
16-Jan 04:31 narn-fd JobId 28511:      /sys is a different filesystem.
Will not descend from / into it.
16-Jan 04:31 narn-fd JobId 28511:      /tmp is a different filesystem.
Will not descend from / into it.
16-Jan 04:31 minbar-fd JobId 28508:      /run is a different filesystem.
Will not descend from / into it.
16-Jan 04:31 minbar-fd JobId 28508:      /sys is a different filesystem.
Will not descend from / into it.
16-Jan 04:31 minbar-fd JobId 28508:      /tmp is a different filesystem.
Will not descend from / into it.
16-Jan 04:31 minbar-dir JobId 28508: Fatal error: sql_create.c:1015
Create db Filename record INSERT INTO Filename (Name) VALUES
('snapper-0.8.15-r1.ebuild') failed. ERR=Duplicate entry
'snapper-0.8.15-r1.ebuild' for key 'Name'
16-Jan 04:31 minbar-dir JobId 28508: Fatal error: catreq.c:664 attribute
create error. ERR=sql_create.c:1015 Create db Filename record INSERT
INTO Filename (Name) VALUES ('snapper-0.8.15-r1.ebuild') failed.
ERR=Duplicate entry 'snapper-0.8.15-r1.ebuild' for key 'Name'
16-Jan 04:31 asgard-fd JobId 28499:      /rpool/nameserver/root/opt/ossh
is a different filesystem. Will not descend from /rpool/nameserver/root
into it.
16-Jan 04:31 asgard-fd JobId 28499:      /rpool/nameserver/root/nfs4 is
a different filesystem. Will not descend from /rpool/nameserver/root
into it.
16-Jan 04:31 asgard-fd JobId 28499:      /rpool/nameserver/root/rpool is
a different filesystem. Will not descend from /rpool/nameserver/root
into it.
16-Jan 04:31 asgard-sd JobId 28499: Elapsed time=00:00:38, Transfer
rate=1.291 M Bytes/second



Running Jobs:
Console connected at 16-Jan-21 13:58
Console connected at 16-Jan-21 14:02
 JobId  Type Level     Files     Bytes  Name              Status
======================================================================
 28508  Back Incr          0         0  Minbar Backup     has a fatal error
 28514  Back Incr          0         0  MySQL Backup New  is waiting for
higher priority jobs to finish



-- 
  Phil Stracchino
  Babylon Communications
  [email protected]
  [email protected]
  Landline: +1.603.293.8485
  Mobile:   +1.603.998.6958