Randomly errors on backup

Hi,
we testes now since Friday and got error. Not sure what exactly happens.
Conditions:

• Cloud: AZURE_BLOB
• 2 Jobs
• 1 concurrent job on Client allowed

Wen we schedule jobst and one of jobs is running directly after another, we receive this error message:

27-Jan 10:43 backup-host JobId 172977: Fatal error: python-fd: Traceback (most recent call last):
  File "/usr/lib/bareos/plugins/BareosFdWrapper.py", line 38, in handle_plugin_event
    return bareos_fd_plugin_object.handle_plugin_event(context, event)
  File "/usr/lib/bareos/plugins/BareosFdPluginBaseclass.py", line 223, in handle_plugin_event
    return self.start_backup_job(context)
  File "/usr/lib/bareos/plugins/BareosFdPluginLibcloud.py", line 322, in start_backup_job
    signal.signal(signal.SIGCHLD, signal.SIG_IGN)
ValueError: signal only works in main thread

27-Jan 10:43 backup-host JobId 172977: Fatal error: fd_plugins.c:654 Command plugin "python:module_path=/usr/lib/bareos/plugins:module_name=bareos-fd-libcloud:provider=AZURE_BLOBS:key=$MY_KEY:secret=$MY_SECRET" requested, but is not loaded.

Any Idea what happens? We also can observe lot of processes bareos-fd after jobs are ended. It seems like not clean destroy from plugin after usage.

Dimi

[JackSlateur]

Hi,

Thank you for the bug report, I am able to reproduce
Can you check out this branch ?
https://github.com/JackSlateur/bareos-libcloud/tree/join

Best regards,

With new children handling our backup server get error middle in backup. Seams to be triggered on exit because except of two childs all other bareos-fd becomes zombie.

Error:
31-Jan 01:08 fhe3-azure-livedooh-backupclient-prod-1.fra1-de.fhe3.int.fsrvz.net-fd JobId 173358: Fatal error: python-fd: Traceback (most recent call last):
  File "/usr/lib/bareos/plugins/BareosFdWrapper.py", line 62, in plugin_io
    return bareos_fd_plugin_object.plugin_io(context, IOP)
  File "/usr/lib/bareos/plugins/BareosFdPluginLibcloud.py", line 398, in plugin_io
    obj = get_object(self.driver, self.job['bucket'], self.job['name'])
  File "/usr/lib/bareos/plugins/BareosFdPluginLibcloud.py", line 94, in get_object
    return driver.get_object(bucket, key)
  File "/usr/local/lib/python2.7/dist-packages/libcloud/storage/drivers/azure_blobs.py", line 467, in get_object
    response = self.connection.request(object_path, method='HEAD')
  File "/usr/local/lib/python2.7/dist-packages/libcloud/common/base.py", line 603, in request
    headers=headers, stream=stream)
  File "/usr/local/lib/python2.7/dist-packages/libcloud/http.py", line 221, in request
    verify=self.verification
  File "/usr/lib/python2.7/dist-packages/requests/sessions.py", line 488, in request
    resp = self.send(prep, **send_kwargs)
  File "/usr/lib/python2.7/dist-packages/requests/sessions.py", line 609, in send
    r = adapter.send(request, **kwargs)
  File "/usr/lib/python2.7/dist-packages/requests/adapters.py", line 487, in send
    raise ConnectionError(e, request=request)
ConnectionError: HTTPSConnectionPool(host='uatccdd.blob.core.windows.net', port=443): Max retries exceeded with url: /uat3/cdn/uploads/57fe4c5738320f2dc1471891.png (Caused by NewConnectionError('<requests.packages.urllib3.connection.VerifiedHTTPSConnection object at 0x7f12a0893e50>: Failed to establish a new connection: [Errno 4] Interrupted system call',))

31-Jan 01:08 backup-host JobId 173358:      Cannot open "uat3/cdn/uploads/57fe4c5738320f2dc1471891.png": ERR=Success.
31-Jan 01:08 backup7-de1-sd JobId 173358: Elapsed time=00:42:32, Transfer rate=5.535 M Bytes/second

Processes:
12808 ? Ssl 7:28 /usr/sbin/bareos-fd
12816 ? Sl 0:01 _ /usr/sbin/bareos-fd
12823 ? Z 0:00 _ [bareos-fd]
12824 ? Z 0:00 _ [bareos-fd]
12825 ? Z 0:00 _ [bareos-fd]
12828 ? Z 0:00 _ [bareos-fd]
12830 ? Z 0:00 _ [bareos-fd]
12831 ? Z 0:00 _ [bareos-fd]
12833 ? Z 0:00 _ [bareos-fd]
12835 ? Z 0:00 _ [bareos-fd]
12836 ? Z 0:00 _ [bareos-fd]
12838 ? Z 0:00 _ [bareos-fd]
12839 ? Z 0:00 _ [bareos-fd]
12843 ? Z 0:00 _ [bareos-fd]
12845 ? Z 0:00 _ [bareos-fd]
12846 ? Z 0:00 _ [bareos-fd]
12849 ? Z 0:00 _ [bareos-fd]
12852 ? Z 0:00 _ [bareos-fd]
12856 ? Z 0:00 _ [bareos-fd]
12857 ? Z 0:00 _ [bareos-fd]
12859 ? Z 0:00 _ [bareos-fd]
12860 ? Z 0:00 _ [bareos-fd]
12861 ? Z 0:00 _ [bareos-fd]
12862 ? Z 0:00 _ [bareos-fd]
12864 ? Z 0:00 _ [bareos-fd]
12865 ? Z 0:00 _ [bareos-fd]
12866 ? Z 0:00 _ [bareos-fd]
12881 ? Z 0:00 _ [bareos-fd]
12884 ? Z 0:00 _ [bareos-fd]
12885 ? Z 0:00 _ [bareos-fd]
12888 ? Z 0:00 _ [bareos-fd]
12891 ? Z 0:00 _ [bareos-fd]
12893 ? Z 0:00 _ [bareos-fd]
12895 ? Z 0:00 _ [bareos-fd]
12897 ? Z 0:00 _ [bareos-fd]
12899 ? Z 0:00 _ [bareos-fd]
12900 ? Z 0:00 _ [bareos-fd]
12904 ? Z 0:00 _ [bareos-fd]
12906 ? Z 0:00 _ [bareos-fd]
12908 ? Z 0:00 _ [bareos-fd]
12909 ? Z 0:00 _ [bareos-fd]
12911 ? Z 0:00 _ [bareos-fd]
12913 ? Z 0:00 _ [bareos-fd]
12914 ? Z 0:00 _ [bareos-fd]
12916 ? Z 0:00 _ [bareos-fd]
12917 ? Z 0:00 _ [bareos-fd]
12918 ? Z 0:00 _ [bareos-fd]
12920 ? Z 0:00 _ [bareos-fd]
12921 ? Z 0:00 _ [bareos-fd]
12923 ? Z 0:00 _ [bareos-fd]
12927 ? S 0:07 _ /usr/sbin/bareos-fd

It works better with installation from master, thanks for great job!

However still some trouble randomly. Here output from last night:

Mar 29 02:07:54 backup-client BareosFdPluginLibcloud: [16170] File container1/cdn/playlists/5c76ec932c48e4715991deb1 changed (or new), backuping (1970-01-01 01:00:00 < 2019-02-27 21:01:23)
Mar 29 02:10:19 backup-client BareosFdPluginLibcloud: [16170] File container1/cdn/playlists/5c78bfbf2c48e4715991f556 changed (or new), backuping (1970-01-01 01:00:00 < 2019-03-01 06:14:39)
Mar 29 02:11:21 backup-client BareosFdPluginLibcloud: [16170] File container1/cdn/playlists/5c7b3cef2c48e4715991ed98 changed (or new), backuping (1970-01-01 01:00:00 < 2019-03-03 03:33:20)
Mar 29 02:11:21 backup-client BareosFdPluginLibcloud: [16170] File container1/cdn/playlists/5c7b3cef2c48e4715991f351 changed (or new), backuping (1970-01-01 01:00:00 < 2019-03-03 03:33:20)
Mar 29 02:11:32 backup-client BareosFdPluginLibcloud: [14746] Backuping container1/cdn/playlists/5c76ec932c48e4715991deb1
Mar 29 02:14:33 backup-client BareosFdPluginLibcloud: [14746] Backuping container1/cdn/playlists/5c78bfbf2c48e4715991f556
Mar 29 02:15:10 backup-client BareosFdPluginLibcloud: [16170] File container1/cdn/playlists/5c7cd0bd2c48e4715991f420 changed (or new), backuping (1970-01-01 01:00:00 < 2019-03-04 08:16:13)
Mar 29 02:15:49 backup-client BareosFdPluginLibcloud: [14746] Backuping container1/cdn/playlists/5c7b3cef2c48e4715991f351
Mar 29 02:15:49 backup-client BareosFdPluginLibcloud: [14746] Backuping container1/cdn/playlists/5c7b3cef2c48e4715991ed98
Mar 29 02:20:19 backup-client BareosFdPluginLibcloud: [14746] Backuping container1/cdn/playlists/5c7cd0bd2c48e4715991f420
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991] FATAL ERROR: I am a prefetcher, and I am dying !
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991] Traceback (most recent call last):
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991]   File "/usr/lib/bareos/plugins/BareosFdPluginLibcloud.py", line 111, in __call__
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991]     self.__work()
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991]   File "/usr/lib/bareos/plugins/BareosFdPluginLibcloud.py", line 123, in __work
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991]     obj = get_object(self.driver, job['bucket'], job['name'])
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991]   File "/usr/lib/bareos/plugins/BareosFdPluginLibcloud.py", line 94, in get_object
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991]     return driver.get_object(bucket, key)
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991]   File "/usr/local/lib/python2.7/dist-packages/libcloud/storage/drivers/azure_blobs.py", line 464, in get_object
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991]     container = self.get_container(container_name=container_name)
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991]   File "/usr/local/lib/python2.7/dist-packages/libcloud/storage/drivers/azure_blobs.py", line 447, in get_container
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991]     method='HEAD')
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991]   File "/usr/local/lib/python2.7/dist-packages/libcloud/common/base.py", line 603, in request
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991]     headers=headers, stream=stream)
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991]   File "/usr/local/lib/python2.7/dist-packages/libcloud/http.py", line 221, in request
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991]     verify=self.verification
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991]   File "/usr/local/lib/python2.7/dist-packages/requests/sessions.py", line 533, in request
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991]     resp = self.send(prep, **send_kwargs)
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991]   File "/usr/local/lib/python2.7/dist-packages/requests/sessions.py", line 646, in send
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991]     r = adapter.send(request, **kwargs)
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991]   File "/usr/local/lib/python2.7/dist-packages/requests/adapters.py", line 498, in send
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991]     raise ConnectionError(err, request=request)
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991] ConnectionError: ('Connection aborted.', error(104, 'Connection reset by peer'))
Mar 29 02:40:56 backup-client BareosFdPluginLibcloud: [15991]

Feel free to give us more to test :)

I think it is related on multiprocessing because we also see lot of zombie processes until all prefetches are joined.

Dimitrij