The traceback suggests some problem in the is_cleaning_tape function.
It might be useful to do
gdb /opt/bacula/bin/bacula-dir
disass is_cleaning_tape
__Martin
>>>>> On Sun, 20 May 2018 17:15:40 +0200, Rasmus Linden said:
>
> Hey All !!
>
> I have a strange issue, I hope some of you can help me with. I am currently
> running bacula version: 9.0.7, recently migrated from mysql to postgres.
> Everything is working as expected, except when i try to table a tape and
> stick it in our scratch pool, bacula-dir crashes with a bang !
> I have set the debug level to 10, and pasted the traceback.
> The last thing happening before the crash, according to the stack is a sql
> query :
>
> SELECT
> MediaId,VolumeName,VolJobs,VolFiles,VolBlocks,VolBytes,VolABytes,VolHoleBytes,VolHoles,VolMounts,VolErrors,VolWrites,MaxVolBytes,VolCapacityBytes,MediaType,VolStatus,PoolId,VolRetention,VolUseDuration,MaxVolJ
> obs,MaxVolFiles,Recycle,Slot,FirstWritten,LastWritten,InChanger,EndFile,EndBlock,VolType,VolParts,VolCloudParts,LastPartBytes,LabelType,LabelDate,StorageId,Enabled,LocationId,RecycleCount,InitialWrite,ScratchPoolId,RecyclePoolId
> ,VolReadTime,VolWriteTime,ActionOnPurge,CacheRetention FROM Media WHERE
> VolumeName=‘B00110L6'
>
> I have tried running the query by hand, and it does not fail *screenshot from
> pgadmin attached.
>
> If i label the volume and stick it into a none scratch pool, it completes
> with no error.
>
> Any suggestion on how to fix is mostly appreciated !
>
> All the best
>
> Ras
>
>
>
> BCONSOLE FAILING IN SCRATCH POOL:
> [root@technicos ~]# bconsole
> Connecting to Director technicos:9101
> 1000 OK: 103 director.xxx.xxxVersion: 9.0.7 (18 April 2018)
> Enter a period to cancel a command.
> *label barcodes slots=3
> Automatically selected Catalog: MyCatalog
> Using Catalog "MyCatalog"
> The defined Storage resources are:
> 1: Autochanger
> 2: LTO6-01
> Select Storage resource (1-2): 1
> Connecting to Storage daemon Autochanger at technicos.xxx:9103 ...
> Connecting to Storage daemon Autochanger at technicos.xxx:9103 ...
> 3306 Issuing autochanger "slots" command.
> Device "Autochanger" has 48 slots.
> Connecting to Storage daemon Autochanger at technicos.xxx:9103 ...
> 3306 Issuing autochanger "list" command.
> The following Volumes will be labeled:
> Slot Volume
> ==============
> 3 B00110L6
> Do you want to label these Volumes? (yes|no): yes
> Defined Pools:
> 1: Archive
> 2: Default
> 3: File
> 4: ProjectsArchive
> 5: Scratch
> Select the Pool (1-5): 5
> [root@technicos ~]#
>
>
> CONSOLE SUCCESS WITH ANOTHER POOL:
> *label barcodes slots=3
> Automatically selected Catalog: MyCatalog
> Using Catalog "MyCatalog"
> The defined Storage resources are:
> 1: Autochanger
> 2: LTO6-01
> Select Storage resource (1-2): 1
> Connecting to Storage daemon Autochanger at technicos.xxx:9103 ...
> Connecting to Storage daemon Autochanger at technicos.xxx:9103 ...
> 3306 Issuing autochanger "slots" command.
> Device "Autochanger" has 48 slots.
> Connecting to Storage daemon Autochanger at technicos.xxx:9103 ...
> 3306 Issuing autochanger "list" command.
> The following Volumes will be labeled:
> Slot Volume
> ==============
> 3 B00110L6
> Do you want to label these Volumes? (yes|no): yes
> Defined Pools:
> 1: Archive
> 2: Default
> 3: File
> 4: ProjectsArchive
> 5: Scratch
> Select the Pool (1-5): 4
> Connecting to Storage daemon Autochanger at technicos.xxx:9103 ...
> Sending label command for Volume "B00110L6" Slot 3 ...
> 3307 Issuing autochanger "unload Volume *Unknown*, Slot 2, Drive 0" command.
> 3304 Issuing autochanger "load Volume B00110L6, Slot 3, Drive 0" command.
> 3305 Autochanger "load Volume B00110L6, Slot 3, Drive 0", status is OK.
> 3000 OK label. VolBytes=64512 VolABytes=0 VolType=0 Volume="B00110L6"
> Device="LTO6-01" (/dev/nst0)
> Catalog record for Volume "B00110L6", Slot 3 successfully created.
> *
>
>
>
> TRACEBACK
> more /opt/bacula/working/bacula.16939.traceback
> [New LWP 23316]
> [New LWP 22394]
> [New LWP 16942]
> [New LWP 16941]
> [Thread debugging using libthread_db enabled]
> Using host libthread_db library "/lib64/libthread_db.so.1".
> 0x00007fb138e9ef3d in nanosleep () from /usr/lib64/libpthread.so.0
> $1 = "20-May-2018 16:50:22\000\000\000\000\000\000\000\000\000"
> $2 = '\000' <repeats 127 times>
> $3 = 0xae1048 "bacula-dir"
> $4 = 0xae1088 "/opt/bacula/bin/bacula-dir"
> $5 = 0x0
> $6 = "PostgreSQL", '\000' <repeats 39 times>
> $7 = 0x7fb1390feeee "9.0.7 (18 April 2018)"
> $8 = 0x7fb1390feecc "x86_64-pc-linux-gnu"
> $9 = 0x7fb1390feec5 "redhat"
> $10 = 0x7fb1390feee7 "(Core)"
> $11 = "technicos", '\000' <repeats 40 times>
> $12 = 0x7fb1390feee0 "redhat (Core)"
> Environment variable "TestName" not defined.
> #0 0x00007fb138e9ef3d in nanosleep () from /usr/lib64/libpthread.so.0
> #1 0x00007fb1390c0688 in bmicrosleep (sec=sec@entry=60, usec=usec@entry=0)
> at bsys.c:178
> #2 0x0000000000437c77 in wait_for_next_job (one_shot_job_to_run=<optimized
> out>) at scheduler.c:121
> #3 0x000000000040dde7 in main (argc=<optimized out>, argv=<optimized out>)
> at dird.c:382
>
> Thread 5 (Thread 0x7fb12e16e700 (LWP 16941)):
> #0 0x00007fb138194c73 in select () from /usr/lib64/libc.so.6
> #1 0x00007fb1390c3d08 in bnet_thread_server (addrs=addrs@entry=0xae5d98,
> max_clients=<optimized out>, client_wq=client_wq@entry=0x6988c0 <ua_workq>,
> handle_client_request=handle_client_request@entry=0x45a800 <handle_UA_client_r
> equest(void*)>) at bnet_server.c:166
> #2 0x000000000045a43c in connect_thread (arg=0xae5d98) at ua_server.c:72
> #3 0x00007fb138e97e25 in start_thread () from /usr/lib64/libpthread.so.0
> #4 0x00007fb13819dbad in clone () from /usr/lib64/libc.so.6
>
> Thread 4 (Thread 0x7fb12d96d700 (LWP 16942)):
> #0 0x00007fb138e9bd42 in pthread_cond_timedwait@@GLIBC_2.3.2 () from
> /usr/lib64/libpthread.so.0
> #1 0x00007fb1390f31b5 in watchdog_thread (arg=<optimized out>) at
> watchdog.c:299
> #2 0x00007fb138e97e25 in start_thread () from /usr/lib64/libpthread.so.0
> #3 0x00007fb13819dbad in clone () from /usr/lib64/libc.so.6
>
> Thread 3 (Thread 0x7fb12d16c700 (LWP 22394)):
> #0 0x00007fb138e9e7fd in read () from /usr/lib64/libpthread.so.0
> #1 0x00007fb1390c297e in read_nbytes (bsock=bsock@entry=0x7fb1280008e8,
> ptr=ptr@entry=0x7fb12d16bcdc "", nbytes=nbytes@entry=4) at bnet.c:74
> #2 0x00007fb1390c6464 in BSOCK::recv (this=this@entry=0x7fb1280008e8) at
> bsock.c:753
> #3 0x000000000045a92a in handle_UA_client_request (arg=0x7fb1280008e8) at
> ua_server.c:131
> #4 0x00007fb1390f3a83 in workq_server (arg=0x6988c0 <ua_workq>) at
> workq.c:372
> #5 0x00007fb138e97e25 in start_thread () from /usr/lib64/libpthread.so.0
> #6 0x00007fb13819dbad in clone () from /usr/lib64/libc.so.6
>
> Thread 2 (Thread 0x7fb127565700 (LWP 23316)):
> #0 0x00007fb138e9f279 in waitpid () from /usr/lib64/libpthread.so.0
> #1 0x00007fb1390ea74a in signal_handler (sig=11) at signal.c:233
> #2 <signal handler called>
> #3 0x00007fb13820dff1 in __strlen_sse2_pminub () from /usr/lib64/libc.so.6
> #4 0x0000000000444dae in is_cleaning_tape (pr=0x7fb127563e80,
> mr=0x7fb127564680, ua=0x7fb11c001f48) at ua_label.c:1005
> #5 label_from_barcodes (drive=0, ua=0x7fb11c001f48) at ua_label.c:583
> #6 do_label (ua=0x7fb11c001f48, relabel=<optimized out>, cmd=<optimized
> out>) at ua_label.c:361
> #7 0x000000000043a145 in do_a_command (ua=0x7fb11c001f48) at ua_cmds.c:253
> #8 0x000000000045a8c3 in handle_UA_client_request (arg=0x7fb128003108) at
> ua_server.c:138
> #9 0x00007fb1390f3a83 in workq_server (arg=0x6988c0 <ua_workq>) at
> workq.c:372
> #10 0x00007fb138e97e25 in start_thread () from /usr/lib64/libpthread.so.0
> #11 0x00007fb13819dbad in clone () from /usr/lib64/libc.so.6
>
> Thread 1 (Thread 0x7fb139f8c880 (LWP 16939)):
> #0 0x00007fb138e9ef3d in nanosleep () from /usr/lib64/libpthread.so.0
> #1 0x00007fb1390c0688 in bmicrosleep (sec=sec@entry=60, usec=usec@entry=0)
> at bsys.c:178
> #2 0x0000000000437c77 in wait_for_next_job (one_shot_job_to_run=<optimized
> out>) at scheduler.c:121
> #3 0x000000000040dde7 in main (argc=<optimized out>, argv=<optimized out>)
> at dird.c:382
> #0 0x00007fb138e9ef3d in nanosleep () from /usr/lib64/libpthread.so.0
> No symbol table info available.
> #1 0x00007fb1390c0688 in bmicrosleep (sec=sec@entry=60, usec=usec@entry=0)
> at bsys.c:178
> 178 stat = nanosleep(&timeout, NULL);
> timeout = {tv_sec = 60, tv_nsec = 0}
> tv = {tv_sec = 210453397560, tv_usec = 140399143188541}
> tz = {tz_minuteswest = 24, tz_dsttime = 0}
> stat = <optimized out>
> #2 0x0000000000437c77 in wait_for_next_job (one_shot_job_to_run=<optimized
> out>) at scheduler.c:121
> 121 bmicrosleep(next_check_secs, 0); /* recheck once per minute */
> jcr = <optimized out>
> job = <optimized out>
> run = <optimized out>
> now = <optimized out>
> prev = <optimized out>
> first = false
> next_job = <optimized out>
> #3 0x000000000040dde7 in main (argc=<optimized out>, argv=<optimized out>)
> at dird.c:382
> 382 while ( (jcr = wait_for_next_job(runjob)) ) {
> jcr = <optimized out>
> ch = <optimized out>
> no_signals = false
> uid = 0x0
> gid = 0x0
> mode = <optimized out>
> #0 0x0000000000000000 in ?? ()
> No symbol table info available.
> #0 0x0000000000000000 in ?? ()
> No symbol table info available.
> #0 0x0000000000000000 in ?? ()
> No symbol table info available.
> #0 0x0000000000000000 in ?? ()
> No symbol table info available.
> Attempt to dump current JCRs. njcrs=3
> threadid=0x7fb139f8c880 JobId=0 JobStatus=R jcr=0xaeb758
> name=*JobMonitor*.2018-05-20_16.46.56_01
> use_count=1 killable=0
> JobType=I JobLevel=
> sched_time=20-May-2018 16:46 start_time=20-May-2018 16:46
> end_time=01-Jan-1970 01:00 wait_time=01-Jan-1970 01:00
> db=(nil) db_batch=(nil) batch_started=0
> wstore=0xae8368 rstore=(nil) wjcr=(nil) client=0xae7918
> reschedule_count=0 SD_msg_chan_started=0
> threadid=0x7fb12d16c700 JobId=0 JobStatus=R jcr=0x7fb1200008e8
> name=-Console-.2018-05-20_16.49.43_03
> use_count=1 killable=0
> JobType=U JobLevel=
> sched_time=20-May-2018 16:49 start_time=20-May-2018 16:49
> end_time=01-Jan-1970 01:00 wait_time=01-Jan-1970 01:00
> db=0x7fb120002618 db_batch=(nil) batch_started=0
> wstore=0xae8368 rstore=(nil) wjcr=(nil) client=0xae7918
> reschedule_count=0 SD_msg_chan_started=0
> BDB=0x7fb120002618 db_name=bacula db_user=bacula connected=true
> cmd="sql_get.c:1213 Media record for Volume name "B00112L6" not found.
> " changes=0
> RWLOCK=0x7fb120002630 w_active=0 w_wait=0
> threadid=0x7fb127565700 JobId=0 JobStatus=R jcr=0x7fb11c0008e8
> name=-Console-.2018-05-20_16.50.10_04
> use_count=1 killable=0
> JobType=U JobLevel=
> sched_time=20-May-2018 16:50 start_time=20-May-2018 16:50
> end_time=01-Jan-1970 01:00 wait_time=01-Jan-1970 01:00
> db=0x7fb120002e58 db_batch=(nil) batch_started=0
> wstore=0xae8368 rstore=(nil) wjcr=(nil) client=0xae7918
> reschedule_count=0 SD_msg_chan_started=0
> BDB=0x7fb120002e58 db_name=bacula db_user=bacula connected=true
> cmd="SELECT
> MediaId,VolumeName,VolJobs,VolFiles,VolBlocks,VolBytes,VolABytes,VolHoleBytes,VolHoles,VolMounts,VolErrors,VolWrites,MaxVolBytes,VolCapacityBytes,MediaType,VolStatus,PoolId,VolRetention,VolUseDuration,MaxVolJ
> obs,MaxVolFiles,Recycle,Slot,FirstWritten,LastWritten,InChanger,EndFile,EndBlock,VolType,VolParts,VolCloudParts,LastPartBytes,LabelType,LabelDate,StorageId,Enabled,LocationId,RecycleCount,InitialWrite,ScratchPoolId,RecyclePoolId
> ,VolReadTime,VolWriteTime,ActionOnPurge,CacheRetention FROM Media WHERE
> VolumeName='B00110L6'" changes=0
> RWLOCK=0x7fb120002e70 w_active=0 w_wait=0
> List plugins. Hook count=0
>
>
>
>
>
------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot
_______________________________________________
Bacula-users mailing list
Bacula-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bacula-users
