08-Jun-2018 15:02:32.782749 bareos-sd (50): dir_cmd.c:442-0 level=250 trace=1 timestamp=1 tracefilename=/var/lib/bareos/bareos-sd.trace 08-Jun-2018 15:02:32.784275 bareos-sd (250): sd_plugins.c:322-0 No bplugin_list: generate_plugin_event ignored. 08-Jun-2018 15:02:32.784304 bareos-sd (200): job.c:458-0 Start stored free_jcr 08-Jun-2018 15:02:32.784326 bareos-sd (200): job.c:585-0 End stored free_jcr 08-Jun-2018 15:03:16.788693 bareos-sd (110): socket_server.c:80-0 Conn: Hello Director bareos-dir-dir calling 08-Jun-2018 15:03:16.788771 bareos-sd (110): socket_server.c:98-0 Got a DIR connection at 08-Jun-2018 15:03:16 08-Jun-2018 15:03:16.788809 bareos-sd (250): sd_plugins.c:629-0 === enter new_plugins === 08-Jun-2018 15:03:16.788835 bareos-sd (250): sd_plugins.c:631-0 No sd plugin list! 08-Jun-2018 15:03:16.789074 bareos-sd (50): cram-md5.c:68-0 send: auth cram-md5 <1814402712.1528470196@bareos-sd> ssl=2 08-Jun-2018 15:03:16.790804 bareos-sd (100): cram-md5.c:123-0 cram-get received: auth cram-md5 <1764404931.1528470196@bareos-dir-dir> ssl=2 08-Jun-2018 15:03:16.790847 bareos-sd (99): cram-md5.c:143-0 sending resp to challenge: b4Bo1B0Fc8tTc4824xAV0C 08-Jun-2018 15:03:16.879071 bareos-sd (50): bnet.c:147-0 TLS server negotiation established. 08-Jun-2018 15:03:16.879309 bareos-sd (90): dir_cmd.c:285-0 Message channel init completed. 08-Jun-2018 15:03:16.920792 bareos-sd (199): dir_cmd.c:296-0 dird jid=4028: 3000 OK Job SDid=2 SDtime=1527087369 Authorization=CHNG-MCCL-EAHO-HCMI-CBDJ-MKIK-ECLG-JCLF 08-Jun-2018 15:03:16.921130 bareos-sd (250): sd_plugins.c:322-4028 No bplugin_list: generate_plugin_event ignored. 08-Jun-2018 15:03:16.922107 bareos-sd (199): dir_cmd.c:296-4028 device->label_block_size) as dev->max_block_size is zero 08-Jun-2018 15:03:16.964066 bareos-sd (200): acquire.c:799-4028 Attach Jid=4028 dcr=7f5134033598 size=0 dev="S3Droplet-lon-001" (S3) 08-Jun-2018 15:03:16.964096 bareos-sd (150): reserve.c:769-4028 call reserve for append: have_vol=0 vol= 08-Jun-2018 15:03:16.964126 bareos-sd (150): reserve.c:970-4028 reserve_append device is "S3Droplet-lon-001" (S3) 08-Jun-2018 15:03:16.964154 bareos-sd (150): reserve.c:1076-4028 PrefMnt=1 exact=1 suitable=1 chgronly=0 any=0 08-Jun-2018 15:03:16.964179 bareos-sd (150): reserve.c:1031-4028 MaxJobs=0 Jobs=0 reserves=0 Status= Vol= 08-Jun-2018 15:03:16.964204 bareos-sd (150): reserve.c:1205-4028 OK Dev avail reserved "S3Droplet-lon-001" (S3) 08-Jun-2018 15:03:16.964229 bareos-sd (250): sd_plugins.c:322-4028 No bplugin_list: generate_plugin_event ignored. 08-Jun-2018 15:03:16.964253 bareos-sd (150): reserve.c:134-4028 Inc reserve=0 dev="S3Droplet-lon-001" (S3) 08-Jun-2018 15:03:16.964277 bareos-sd (150): reserve.c:778-4028 Reserved=1 dev_name=S3Droplet-lon-001 mediatype=s3bucket pool=S3DropletTest-Full ok=1 08-Jun-2018 15:03:16.964302 bareos-sd (150): reserve.c:780-4028 Vol= num_writers=0, have_vol=0 08-Jun-2018 15:03:16.964327 bareos-sd (150): reserve.c:791-4028 no vol, call find_next_appendable_vol. 08-Jun-2018 15:03:16.964356 bareos-sd (50): askdir.c:275-4028 dir_find_next_appendable_volume: reserved=1 Vol= 08-Jun-2018 15:03:16.964404 bareos-sd (50): askdir.c:295-4028 >dird CatReq Job=s3-my-client.2018-06-08_15.03.14_04 FindMedia=1 pool_name=S3DropletTest-Full media_type=s3bucket unwanted_volumes= 08-Jun-2018 15:03:16.968478 bareos-sd (50): askdir.c:179-4028 VolMinBlocksize(0) to vol.VolMinBlocksize(0) 08-Jun-2018 15:03:16.968562 bareos-sd (50): askdir.c:219-4028 setting dcr->VolMaxBlocksize(0) to vol.VolMaxBlocksize(0) 08-Jun-2018 15:03:16.968585 bareos-sd (150): vol_mgr.c:223-4028 find_read_vol: read_vol_list empty. 08-Jun-2018 15:03:16.968614 bareos-sd (150): vol_mgr.c:930-4028 Vol=S3DropletTest-Full-3030 not in use. 08-Jun-2018 15:03:16.968635 bareos-sd (50): askdir.c:306-4028 Call reserve_volume for write. Vol=S3DropletTest-Full-3030 08-Jun-2018 15:03:16.968657 bareos-sd (150): vol_mgr.c:400-4028 enter reserve_volume=S3DropletTest-Full-3030 drive="S3Droplet-lon-001" (S3) 08-Jun-2018 15:03:16.968698 bareos-sd (150): vol_mgr.c:287-4028 new Vol=S3DropletTest-Full-3030 at 7f513402e3e8 dev="S3Droplet-lon-001" (S3) 08-Jun-2018 15:03:16.968741 bareos-sd (150): vol_mgr.c:569-4028 === set in_use. vol=S3DropletTest-Full-3030 dev="S3Droplet-lon-001" (S3) 08-Jun-2018 15:03:16.968764 bareos-sd (150): vol_mgr.c:606-4028 Inc walk_start use_count=2 volname=S3DropletTest-Full-3030 08-Jun-2018 15:03:16.968786 bareos-sd (150): vol_mgr.c:268-4028 List end new volume: S3DropletTest-Full-3030 in_use=1 swap=0 on device "S3Droplet-lon-001" (S3) 08-Jun-2018 15:03:16.968820 bareos-sd (50): askdir.c:311-4028 dir_find_next_appendable_volume return true. vol=S3DropletTest-Full-3030 08-Jun-2018 15:03:16.968843 bareos-sd (150): reserve.c:795-4028 looking for Volume=S3DropletTest-Full-3030 08-Jun-2018 15:03:16.968887 bareos-sd (150): reserve.c:854-4028 >dird: 3000 OK use device device=S3Droplet-lon-001 08-Jun-2018 15:03:16.968911 bareos-sd (150): reserve.c:657-4028 Device S3Droplet-lon-001 reserved=1 for append. 08-Jun-2018 15:03:16.968932 bareos-sd (150): reserve.c:570-4028 available device found=S3Droplet-lon-001 08-Jun-2018 15:03:16.968958 bareos-sd (150): reserve.c:584-4028 OK dev found. Vol=S3DropletTest-Full-3030 08-Jun-2018 15:03:16.969837 bareos-sd (199): dir_cmd.c:296-4028 ssl=2 08-Jun-2018 15:03:32.247954 bareos-sd (100): cram-md5.c:123-0 cram-get received: auth cram-md5 <1145284880.1528470212@bareos-dir-dir> ssl=2 08-Jun-2018 15:03:32.248008 bareos-sd (99): cram-md5.c:143-0 sending resp to challenge: 6mB2OmcA6AdzER+05C+3WC 08-Jun-2018 15:03:32.338125 bareos-sd (50): bnet.c:147-0 TLS server negotiation established. 08-Jun-2018 15:03:32.338387 bareos-sd (90): dir_cmd.c:285-0 Message channel init completed. 08-Jun-2018 15:03:32.379686 bareos-sd (199): dir_cmd.c:296-0 ssl=2 08-Jun-2018 15:03:32.426086 bareos-sd (100): cram-md5.c:123-0 cram-get received: auth cram-md5 <812216031.1528470212@bareos-dir-dir> ssl=2 08-Jun-2018 15:03:32.426132 bareos-sd (99): cram-md5.c:143-0 sending resp to challenge: biFrH6lWp+o2W4/Qb0ACVB 08-Jun-2018 15:03:32.515011 bareos-sd (50): bnet.c:147-0 TLS server negotiation established. 08-Jun-2018 15:03:32.515247 bareos-sd (90): dir_cmd.c:285-0 Message channel init completed. 08-Jun-2018 15:03:32.556699 bareos-sd (199): dir_cmd.c:296-0 ssl=2 08-Jun-2018 15:03:32.602970 bareos-sd (100): cram-md5.c:123-0 cram-get received: auth cram-md5 <1766581868.1528470212@bareos-dir-dir> ssl=2 08-Jun-2018 15:03:32.603008 bareos-sd (99): cram-md5.c:143-0 sending resp to challenge: l2/Kt9/45ysbHUB745/2MB 08-Jun-2018 15:03:32.692341 bareos-sd (50): bnet.c:147-0 TLS server negotiation established. 08-Jun-2018 15:03:32.692586 bareos-sd (90): dir_cmd.c:285-0 Message channel init completed. 08-Jun-2018 15:03:32.733691 bareos-sd (199): dir_cmd.c:296-0 ssl=2 08-Jun-2018 15:05:24.611609 bareos-sd (100): cram-md5.c:123-0 cram-get received: auth cram-md5 <525357092.1528470324@my-client-fd> ssl=2 08-Jun-2018 15:05:24.611657 bareos-sd (99): cram-md5.c:143-0 sending resp to challenge: OG/4H/+xaH9Ya7/fqH/RtC 08-Jun-2018 15:05:24.671404 bareos-sd (50): bnet.c:147-0 TLS server negotiation established. 08-Jun-2018 15:05:24.671629 bareos-sd (50): fd_cmds.c:148-0 OK Authentication jid=4028 Job s3-my-client.2018-06-08_15.03.14_04 08-Jun-2018 15:05:24.671682 bareos-sd (50): job.c:203-4028 Auth=1 canceled=0 errstat=0 08-Jun-2018 15:05:24.671745 bareos-sd (120): fd_cmds.c:177-4028 Start run Job=s3-my-client.2018-06-08_15.03.14_04 08-Jun-2018 15:06:02.788438 bareos-sd (110): socket_server.c:80-0 Conn: Hello Director bareos-dir-dir calling 08-Jun-2018 15:06:02.788485 bareos-sd (110): socket_server.c:98-0 Got a DIR connection at 08-Jun-2018 15:06:02 08-Jun-2018 15:06:02.788536 bareos-sd (250): sd_plugins.c:629-0 === enter new_plugins === 08-Jun-2018 15:06:02.788557 bareos-sd (250): sd_plugins.c:631-0 No sd plugin list! 08-Jun-2018 15:06:02.788760 bareos-sd (50): cram-md5.c:68-0 send: auth cram-md5 <1274885111.1528470362@bareos-sd> ssl=2 08-Jun-2018 15:06:02.790525 bareos-sd (100): cram-md5.c:123-0 cram-get received: auth cram-md5 <2140094375.1528470362@bareos-dir-dir> ssl=2 08-Jun-2018 15:06:02.790574 bareos-sd (99): cram-md5.c:143-0 sending resp to challenge: s4JgZR/lXm/S0k+fP9gfFD 08-Jun-2018 15:06:02.881143 bareos-sd (50): bnet.c:147-0 TLS server negotiation established. 08-Jun-2018 15:06:02.881418 bareos-sd (90): dir_cmd.c:285-0 Message channel init completed. 08-Jun-2018 15:06:02.922769 bareos-sd (199): dir_cmd.c:296-0 ssl=2 08-Jun-2018 15:06:02.971747 bareos-sd (100): cram-md5.c:123-0 cram-get received: auth cram-md5 <1934344625.1528470362@bareos-dir-dir> ssl=2 08-Jun-2018 15:06:02.971789 bareos-sd (99): cram-md5.c:143-0 sending resp to challenge: 0X89mD+kTXdQ7/+Gm8QQ/C 08-Jun-2018 15:06:03.060839 bareos-sd (50): bnet.c:147-0 TLS server negotiation established. 08-Jun-2018 15:06:03.061106 bareos-sd (90): dir_cmd.c:285-0 Message channel init completed. 08-Jun-2018 15:06:03.102789 bareos-sd (199): dir_cmd.c:296-0 ssl=2 08-Jun-2018 15:06:03.150387 bareos-sd (100): cram-md5.c:123-0 cram-get received: auth cram-md5 <483538177.1528470363@bareos-dir-dir> ssl=2 08-Jun-2018 15:06:03.150440 bareos-sd (99): cram-md5.c:143-0 sending resp to challenge: //c5S2sojXwn77/nbSkezD 08-Jun-2018 15:06:03.240121 bareos-sd (50): bnet.c:147-0 TLS server negotiation established. 08-Jun-2018 15:06:03.240383 bareos-sd (90): dir_cmd.c:285-0 Message channel init completed. 08-Jun-2018 15:06:03.281661 bareos-sd (199): dir_cmd.c:296-0 filed: 3000 OK open ticket = 2 08-Jun-2018 15:06:23.515415 bareos-sd (110): fd_cmds.c:221-4028 dird CatReq Job=s3-my-client.2018-06-08_15.03.14_04 GetVolInfo VolName=S3DropletTest-Full-3030 write=1 08-Jun-2018 15:06:23.517563 bareos-sd (50): askdir.c:179-4028 VolMinBlocksize(0) to vol.VolMinBlocksize(0) 08-Jun-2018 15:06:23.517668 bareos-sd (50): askdir.c:219-4028 setting dcr->VolMaxBlocksize(0) to vol.VolMaxBlocksize(0) 08-Jun-2018 15:06:23.517796 bareos-sd (150): mount.c:126-4028 After find_next_append. Vol=S3DropletTest-Full-3030 Slot=0 08-Jun-2018 15:06:23.517818 bareos-sd (100): autochanger.c:118-4028 Device "S3Droplet-lon-001" (S3) is not an autochanger 08-Jun-2018 15:06:23.517868 bareos-sd (150): mount.c:176-4028 autoload_dev returns 0 08-Jun-2018 15:06:23.517900 bareos-sd (250): mount.c:193-4028 (2)Ask=0 08-Jun-2018 15:06:23.517934 bareos-sd (250): mount.c:196-4028 Ask=0 autochanger=0 08-Jun-2018 15:06:23.517956 bareos-sd (150): mount.c:212-4028 want vol=S3DropletTest-Full-3030 devvol= dev="S3Droplet-lon-001" (S3) 08-Jun-2018 15:06:23.517981 bareos-sd (100): dev.c:565-4028 open dev: type=6 dev_name="S3Droplet-lon-001" (S3) vol=S3DropletTest-Full-3030 mode=OPEN_READ_WRITE 08-Jun-2018 15:06:23.518004 bareos-sd (250): sd_plugins.c:322-4028 No bplugin_list: generate_plugin_event ignored. 08-Jun-2018 15:06:23.518025 bareos-sd (100): dev.c:584-4028 call open_device mode=OPEN_READ_WRITE 08-Jun-2018 15:06:23.518116 bareos-sd (190): dev.c:1029-4028 Enter mount 08-Jun-2018 15:06:23.518137 bareos-sd (250): sd_plugins.c:322-4028 No bplugin_list: generate_plugin_event ignored. 08-Jun-2018 15:06:23.518175 bareos-sd (100): dev.c:658-4028 open disk: mode=OPEN_READ_WRITE open(S3/S3DropletTest-Full-3030, 00000002, 0640) 08-Jun-2018 15:06:23.518615 bareos-sd (10): droplet_device.c:97-4028 : info: src/droplet.c:127: dpl_init: PRNG has been seeded with enough data