guess_file_type, xattrfile - "path does not exist anymore => we removed corresponding attributes in redis"

[matthieumarrast]

My mfdata module is treating 40000 files per day with classical plugin chain:

[guess_file_type] => [switch] => [plugin_foo] => [switch] => [plugin_bar]

but for a couple of files per day the log of the guess_file_type plugin shows in its log that the tags of the file are removed (in redis) :

2023-02-03T03:41:39.225179Z     [INFO] (mfdata.guess_file_type.main#3517739) File /home/mfdata/var/in/tmp/guess_file_type.main/598b888b33a144cca215393e3953d293 moved to /home/mfdata/var/in/step.switch.main/598b888b33a144cca215393e3953d293
2023-02-03T03:41:39.225661Z     [INFO] (mfdata.guess_file_type.main#3517739) End of the /home/mfdata/var/in/incoming/PTKG85_HUMI_041200.20230204120000.198491.LT processing after 3 ms
2023-02-03T03:41:39.233049Z  [WARNING] (xattrfile#3517739) /home/mfdata/var/in/step.switch.main/598b888b33a144cca215393e3953d293 path does not exist anymore => we removed corresponding attributes in redis

This removal occurs when plugin_foo is treating the file.
So when the file is forwarded to plugin switch, as the tags are lost, the file is forwarded again to plugin_foo... annoying !

I have no idea why the __del__ method of the XattrFile file (https://github.com/metwork-framework/xattrfile/blob/master/xattrfile/__init__.py) is executed after the end of the guess_file_type treatment.

[thebaptiste]

Only "annoying" or serious ? Is the file finally lost or not routed to its destination ?

[matthieumarrast]

The problem occurs once this week-end, here are complete logs:

1. GUESS_FILE_TYPE:

2023-02-04T15:36:39.900004Z     [INFO] (mfdata.guess_file_type.main#23676) Start the processing of /home/mfdata/var/in/incoming/PTDW50_HUMI_042100.20230204210000.135104.LT...
2023-02-04T15:36:39.900393Z     [INFO] (mfdata.guess_file_type.main#23676) Move /home/mfdata/var/in/incoming/PTDW50_HUMI_042100.20230204210000.135104.LT to /home/mfdata/var/in/tmp/guess_file_type.main/773b5b0dd13f4192b340d3a68f233a10 (to process it)
2023-02-04T15:36:39.900650Z     [INFO] (mfdata.guess_file_type.main#23676) Setting tag first.core.original_uid = 773b5b0dd13f4192b340d3a68f233a10
2023-02-04T15:36:39.900850Z     [INFO] (mfdata.guess_file_type.main#23676) Setting tag first.core.original_basename = PTDW50_HUMI_042100.20230204210000.135104.LT
2023-02-04T15:36:39.901105Z     [INFO] (mfdata.guess_file_type.main#23676) Setting tag first.core.original_dirname = incoming
2023-02-04T15:36:39.901242Z     [INFO] (mfdata.guess_file_type.main#23676) Processing file: /home/mfdata/var/in/tmp/guess_file_type.main/773b5b0dd13f4192b340d3a68f233a10
2023-02-04T15:36:39.901387Z     [INFO] (mfdata.guess_file_type.main#23676) Setting tag 0.guess_file_type.main.ascii_header = PNGIHDRBPLTEFFF(
2023-02-04T15:36:39.901490Z     [INFO] (mfdata.guess_file_type.main#23676) Setting tag latest.guess_file_type.main.ascii_header = PNGIHDRBPLTEFFF(
2023-02-04T15:36:39.902015Z     [INFO] (mfdata.guess_file_type.main#23676) Setting tag 0.guess_file_type.main.system_magic = PNG image data, 1500 x 1271, 8-bit colormap, non-interlaced
2023-02-04T15:36:39.902160Z     [INFO] (mfdata.guess_file_type.main#23676) Setting tag latest.guess_file_type.main.system_magic = PNG image data, 1500 x 1271, 8-bit colormap, non-interlaced
2023-02-04T15:36:39.902280Z     [INFO] (mfdata.guess_file_type.main#23676) Setting tag 0.guess_file_type.main.size = 135104
2023-02-04T15:36:39.902376Z     [INFO] (mfdata.guess_file_type.main#23676) Setting tag latest.guess_file_type.main.size = 135104
2023-02-04T15:36:39.905230Z     [INFO] (mfdata.guess_file_type.main#23676) File /home/mfdata/var/in/tmp/guess_file_type.main/773b5b0dd13f4192b340d3a68f233a10 moved to /home/mfdata/var/in/step.switch.main/773b5b0dd13f4192b340d3a68f233a10
2023-02-04T15:36:39.906182Z     [INFO] (mfdata.guess_file_type.main#23676) End of the /home/mfdata/var/in/incoming/PTDW50_HUMI_042100.20230204210000.135104.LT processing after 5 ms

2. SWITCH:
   First file treatment, file is copied to plugin_foo :

2023-02-04T15:36:39.903520Z     [INFO] (mfdata.switch.main#22357) Start the processing of /home/mfdata/var/in/step.switch.main/773b5b0dd13f4192b340d3a68f233a10...
2023-02-04T15:36:39.903886Z     [INFO] (mfdata.switch.main#22357) Move /home/mfdata/var/in/step.switch.main/773b5b0dd13f4192b340d3a68f233a10 to /home/mfdata/var/in/tmp/switch.main/773b5b0dd13f4192b340d3a68f233a10 (to process it)
2023-02-04T15:36:39.904673Z     [INFO] (mfdata.switch.main#22357) Processing file: /home/mfdata/var/in/tmp/switch.main/773b5b0dd13f4192b340d3a68f233a10
2023-02-04T15:36:39.904909Z     [INFO] (mfdata.switch.main#22357) 1 actions matched for file=/home/mfdata/var/in/tmp/switch.main/773b5b0dd13f4192b340d3a68f233a10
2023-02-04T15:36:39.906256Z     [INFO] (mfdata.switch.main#22357) File /home/mfdata/var/in/tmp/switch.main/773b5b0dd13f4192b340d3a68f233a10 copied to /home/mfdata/var/in/step.plugin_foo.main/773b5b0dd13f4192b340d3a68f233a10
2023-02-04T15:36:39.907225Z     [INFO] (mfdata.switch.main#22357) End of the /home/mfdata/var/in/step.switch.main/773b5b0dd13f4192b340d3a68f233a10 processing after 3 ms

3. PLUGIN_FOO:
   (note: the goal of this plugin is to rename a file, by modifying the tag original_basename of the file)
   First file treatment, file is moved to switch:

2023-02-04T15:36:39.907169Z     [INFO] (mfdata.plugin_foo.main#3310) Start the processing of /home/mfdata/var/in/step.plugin_foo.main/773b5b0dd13f4192b340d3a68f233a10...
2023-02-04T15:36:39.907801Z     [INFO] (mfdata.plugin_foo.main#3310) Move /home/mfdata/var/in/step.plugin_foo.main/773b5b0dd13f4192b340d3a68f233a10 to /home/mfdata/var/in/tmp/plugin_foo.main/773b5b0dd13f4192b340d3a68f233a10 (to process it)
2023-02-04T15:36:39.908400Z     [INFO] (mfdata.plugin_foo.main#3310) Processing file: /home/mfdata/var/in/tmp/plugin_foo.main/773b5b0dd13f4192b340d3a68f233a10
2023-02-04T15:36:39.909393Z     [INFO] (mfdata.plugin_foo.main#3310) File /home/mfdata/var/in/tmp/plugin_foo.main/773b5b0dd13f4192b340d3a68f233a10 moved to /home/mfdata/var/in/step.switch.main/773b5b0dd13f4192b340d3a68f233a10

???. GUESS_FILE_TYPE:
Tags are removed, as written in the guess_file_type log:

2023-02-04T15:36:39.909662Z  [WARNING] (xattrfile#23676) /home/mfdata/var/in/step.switch.main/773b5b0dd13f4192b340d3a68f233a10 path does not exist anymore => we removed corresponding attributes in redis

4. SWITCH:
   File "reinjected" to switch by plugin_foo (as tags are lost, they are recreated, and file is fowarded again to plugin_foo):

2023-02-04T15:36:39.910680Z     [INFO] (mfdata.switch.main#22357) Start the processing of /home/mfdata/var/in/step.switch.main/773b5b0dd13f4192b340d3a68f233a10...
2023-02-04T15:36:39.911785Z     [INFO] (mfdata.switch.main#22357) Move /home/mfdata/var/in/step.switch.main/773b5b0dd13f4192b340d3a68f233a10 to /home/mfdata/var/in/tmp/switch.main/43663b19d2514628b82db75d3909bda8 (to process it)
2023-02-04T15:36:39.912274Z     [INFO] (mfdata.switch.main#22357) Setting tag first.core.original_uid = 43663b19d2514628b82db75d3909bda8
2023-02-04T15:36:39.913023Z     [INFO] (mfdata.switch.main#22357) Setting tag first.core.original_basename = 773b5b0dd13f4192b340d3a68f233a10
2023-02-04T15:36:39.914424Z     [INFO] (mfdata.switch.main#22357) Setting tag first.core.original_dirname = step.switch.main
2023-02-04T15:36:39.914724Z     [INFO] (mfdata.switch.main#22357) Processing file: /home/mfdata/var/in/tmp/switch.main/43663b19d2514628b82db75d3909bda8
2023-02-04T15:36:39.915123Z     [INFO] (mfdata.switch.main#22357) 1 actions matched for file=/home/mfdata/var/in/tmp/switch.main/43663b19d2514628b82db75d3909bda8
2023-02-04T15:36:39.916438Z     [INFO] (mfdata.switch.main#22357) File /home/mfdata/var/in/tmp/switch.main/43663b19d2514628b82db75d3909bda8 moved to /home/mfdata/var/in/step.plugin_foo.main/43663b19d2514628b82db75d3909bda8
2023-02-04T15:36:39.917213Z     [INFO] (mfdata.switch.main#22357) End of the /home/mfdata/var/in/step.switch.main/773b5b0dd13f4192b340d3a68f233a10 processing after 5 ms

5. PLUGIN_FOO:
   File treated again by plugin:

2023-02-04T15:36:39.910044Z     [INFO] (mfdata.plugin_foo.main#3310) End of the /home/mfdata/var/in/step.plugin_foo.main/773b5b0dd13f4192b340d3a68f233a10 processing after 2 ms
2023-02-04T15:36:39.916425Z     [INFO] (mfdata.plugin_foo.main#3310) Start the processing of /home/mfdata/var/in/step.plugin_foo.main/43663b19d2514628b82db75d3909bda8...
2023-02-04T15:36:39.916699Z     [INFO] (mfdata.plugin_foo.main#3310) Move /home/mfdata/var/in/step.plugin_foo.main/43663b19d2514628b82db75d3909bda8 to /home/mfdata/var/in/tmp/plugin_foo.main/43663b19d2514628b82db75d3909bda8 (to process it)
2023-02-04T15:36:39.917195Z     [INFO] (mfdata.plugin_foo.main#3310) Processing file: /home/mfdata/var/in/tmp/plugin_foo.main/43663b19d2514628b82db75d3909bda8
2023-02-04T15:36:39.917338Z     [INFO] (mfdata.plugin_foo.main#3310) File 773b5b0dd13f4192b340d3a68f233a10 will be renamed to 773b5b0dd13f4192b340d3a68f233a10.20230204153639917292.43663b19d2514628b82db75d3909bda8
2023-02-04T15:36:39.917931Z     [INFO] (mfdata.plugin_foo.main#3310) File /home/mfdata/var/in/tmp/plugin_foo.main/43663b19d2514628b82db75d3909bda8 moved to /home/mfdata/var/in/step.switch.main/43663b19d2514628b82db75d3909bda8
2023-02-04T15:36:39.918382Z     [INFO] (mfdata.plugin_foo.main#3310) End of the /home/mfdata/var/in/step.plugin_foo.main/43663b19d2514628b82db75d3909bda8 processing after 1 ms

[matthieumarrast]

Only "annoying" or serious ? Is the file finally lost or not routed to its destination ?

The file is routed to its destination but with a wrong name, so finally it is lost.

[matthieumarrast]

I have uninstalled the plugin guess_file_type to check if this issue is still occuring.

[matthieumarrast]

Without guess_file_type the issue does not occur anymore. And I do not need this plugin.

Note that I have also replaced my plugin using AcquisitionStep by an AcquisitionTransformStep, for reinjecting to switch :

Before:

class PluginFoo(AcquisitionStep):
    def process(self, xaf):
        ...
        return self.copy_to_plugin_step(xaf, 'switch', 'main', info=True, keep_original_basename=True)

After:

class PluginFoo(AcquisitionTransformStep):
    def transform(self, xaf):
        ...
        # the move to switch plugin is operated by the inherited process_out()
        # method of class AcquisitionTransformStep, using dest_dir param
        return xaf

with config.ini: dest_dir = switch/main

[matthieumarrast]

and probably a move_to_plugin_step must be prefered to copy_to_plugin_step for reinjecting !!

[thebaptiste]

So it's unclear what was causing the problem :

• something to do with the usage of the plugin guess_file_type
• something to do with the usage of move_to_plugin_step in some corny cases (may be on the occasion of a stop/restart of some process at a "bad moment")
• both
  May be an interesting test would be to keep the plugin guess_file_type and the usage of AcquisitionStep but with move_to_plugin_step...

[matthieumarrast]

You're right, I have reinstalled the guess_file_type plugin with command:

$plugins.install /opt/metwork-mfdata-2.1/share/plugins/guess_file_type-2.1.1-1.metwork.mfdata.plugin
- Checking plugin file...                                  [ OK ]
- Installing plugin guess_file_type...                     [ WARNING ]
2023-02-13T13:46:33.215555Z  [WARNING] (_prepare_plugin_config.py#3767539) /home/mfdata/config/plugins/guess_file_type.ini already exists, we prefer not to override, new file created as: /home/mfdata/config/plugins/guess_file_type.ini.new => please merge them manually

note: I don't understand the above warning. Uninstalling the plugin did not uninstall its config in ~/config/plugins/ ?

I wait for a couple of days to see if the problem occurs with the guess_file_type installed. If not, the problem was maybe related to copy_to_plugin_step... to be continued.

[matthieumarrast]

After guess_file_type reinstallation, the problem occurs again:

2023-02-13T15:37:06.510545Z     [INFO] (mfdata.guess_file_type.main#3803738) Start the processing of /home/mfdata/var/in/incoming/PTCB70_HUMI_13180020230213180000.196040.LT...
2023-02-13T15:37:06.511042Z     [INFO] (mfdata.guess_file_type.main#3803738) Move /home/mfdata/var/in/incoming/PTCB70_HUMI_131800.20230213180000196040.LT to /home/mfdata/var/in/tmp/guess_file_type.main/eb5f31df819040cab03af461573a5510 (to process it)
2023-02-13T15:37:06.511326Z     [INFO] (mfdata.guess_file_type.main#3803738) Setting tag first.core.original_uid = eb5f31df819040cab03af461573a5510
2023-02-13T15:37:06.511514Z     [INFO] (mfdata.guess_file_type.main#3803738) Setting tag first.core.original_basename = PTCB70_HUMI_131800.20230213180000.196040.LT
2023-02-13T15:37:06.512148Z     [INFO] (mfdata.guess_file_type.main#3803738) Setting tag first.core.original_dirname = incoming
2023-02-13T15:37:06.512313Z     [INFO] (mfdata.guess_file_type.main#3803738) Processing file: /home/mfdata/var/in/tmp/guess_file_type.main/eb5f31df819040cab03af461573a5510
2023-02-13T15:37:06.512459Z     [INFO] (mfdata.guess_file_type.main#3803738) Setting tag 0.guess_file_type.main.ascii_header = PNGIHDRY7PLTE'6631
2023-02-13T15:37:06.512557Z     [INFO] (mfdata.guess_file_type.main#3803738) Setting tag latest.guess_file_type.main.ascii_header = PNGIHDRY7PLTE'
2023-02-13T15:37:06.513232Z     [INFO] (mfdata.guess_file_type.main#3803738) Setting tag 0.guess_file_type.main.system_magic = PNG image data, 1290 x 2199, 8-bit colormap, non-interlaced
2023-02-13T15:37:06.513374Z     [INFO] (mfdata.guess_file_type.main#3803738) Setting tag latest.guess_file_type.main.system_magic = PNG image data, 1290 x 2199, 8-bit colormap, non-interlaced
2023-02-13T15:37:06.513488Z     [INFO] (mfdata.guess_file_type.main#3803738) Setting tag 0.guess_file_type.main.size = 196040
2023-02-13T15:37:06.513576Z     [INFO] (mfdata.guess_file_type.main#3803738) Setting tag latest.guess_file_type.main.size = 196040
2023-02-13T15:37:06.514226Z     [INFO] (mfdata.guess_file_type.main#3803738) File /home/mfdata/var/in/tmp/guess_file_type.main/eb5f31df819040cab03af461573a5510 moved to /home/mfdata/var/in/step.switch.main/eb5f31df819040cab03af461573a5510
2023-02-13T15:37:06.514798Z     [INFO] (mfdata.guess_file_type.main#3803738) End of the /home/mfdata/var/in/incoming/PTCB70_HUMI_131800.20230213180000.196040.LT processing after 4 ms
2023-02-13T15:37:06.522479Z  [WARNING] (xattrfile#3803738) /home/mfdata/var/in/step.switch.main/eb5f31df819040cab03af461573a5510 path does not exist anymore => we removed corresponding attributes in redis

Only for ONE file on the last 24 hours. But it's one too many.

[thebaptiste]

I have difficulties to understand this problem...
Did you look for system errors (about inodes maybe) in /var/log/messages ?

[matthieumarrast]

So am I. Very strange issue. Yesterday 14 february it happened 4 times :

2023-02-14T03:36:57.790120Z  [WARNING] (xattrfile#73896) /home/mfdata/var/in/step.switch.main/59ac517f31ad4132bfd41d3f56c1058a path does not exist anymore => we removed corresponding attributes in redis
2023-02-14T03:41:56.410618Z  [WARNING] (xattrfile#73896) /home/mfdata/var/in/step.switch.main/a21dcdc5abf74c4cbc539d0b1f5417e8 path does not exist anymore => we removed corresponding attributes in redis
2023-02-14T09:37:21.093230Z  [WARNING] (xattrfile#301622) /home/mfdata/var/in/step.switch.main/af2c6dd52df44ff888e6e02008448f6a path does not exist anymore => we removed corresponding attributes in redis
2023-02-14T09:37:50.944488Z  [WARNING] (xattrfile#997455) /home/mfdata/var/in/step.switch.main/81d4e56d13bd4acd99c73b0cb7026b45 path does not exist anymore => we removed corresponding attributes in redis

Nothing relevant in /var/log/messages.

The error is about an xattrfile in the input of switch plugin, I think because the guess_file_type copy/move the file to this directory (var/in/step.switch.main)... but its a normal behaviour that the switch plugin then moves this file to its "working" directory ~/var/in/tmp/switch.main/...

[matthieumarrast]

The only code where I find a del xaf is the ping method of reinject_step (https://github.com/metwork-framework/acquisition/blob/master/acquisition/reinject_step.py)

 def ping(self):
...
        if not os.path.exists(filepath):
            del(self.__xafs[filepath])
        mtime, retry_attempt, xaf = self.__xafs[filepath]
        if retry_attempt >= self.retry_total:
            del(self.__xafs[filepath])
            self.give_up(xaf)
        delay = self.delay(retry_attempt + 1)
        if now - mtime >= delay:
            self.reinject(xaf, retry_attempt)
            del(self.__xafs[filepath])
...

But guess_file_type and switch does not use reinject !?