Spotlight's "Last opened" metadata set to arbitrary date and time

[haihige]

Describe the bug

I'm noticing some odd behavior with the "Last opened" timestamp, where it gets updated since the feature was implemented for #2258 (thank you NJRoadfan!), but the dates and times are wrong. For example, all of these were opened on 2026-05-18 at around 20:15 (technically before 4.5.0 was officially released, but this is still present in 4.5.0):

1. Directory 1, file.txt: 2026-03-23 10:55
2. Directory 1, file.png: 2026-04-27 21:05
3. Directory 2, file.gif: 2026-03-23 12:05
4. Drive root, file.txt: doesn't update on file open.

When I disconnect and reconnect to the server, the first time I select one of these files, Finder shows the "Last opened" date that was previously there (normally the same as the "Last modified" date). The second time I select it, it shows the new arbitrary time. Note that this is selecting, not opening.

To Reproduce

Build with Spotlight support, set spotlight = yes in afp.conf, and open some files (but don't modify and save them).

Expected behavior

The last opened date and time should be the correct day and time that the file was opened.

Environment

• Server OS: FreeBSD 14.4 (running in a jail)
• Client OS: Mac OS X Snow Leopard 10.6.8
• Netatalk Version: 4.5.0

Configuration

afp.conf:

[Global]
server name = AFPdev
afp interfaces = epair0b
log level = default:warn
log file = /var/log/afpd.log
mimic model = RackMac
zeroconf = yes
afpstats = yes
spotlight = yes
cnid scheme = sqlite

[data]
path = /mnt/data
valid users = haihige

Logs

Attach syslogs from the malfunctioning process, maxdebug log level

Which process I should set the log level up for?

[rdmark]

thanks for the report! this seems like a valid improvement area.

to answer your question, a good starting point for logging should be:

log level = default:info,spotlight:debug

syntax for logging options documented in the man page:

https://netatalk.io/manual/en/afp.conf.5#logging-options

[NJRoadfan]

When I was testing this feature, I ran into this. Confirm with stat or ls -la what the atime stamp of the files are on the host. Some OSes don't update atime real time on every file access to reduce overhead. Linux defaults to relatime style updating, which means the timestamp is only updated when it exceeds a certain amount of time from the old timestamp. ZFS also has this option at the filesystem level and it may be enabled by default on some OSes.

As discussed in the last issue, this is a bit of a hack. Actual macOS AFP server SpotlightRPC calls return the value of the com.apple.lastuseddate#PS extended attribute if its present on a file for the "Last Opened" value. Even this value isn't accurate since it is only updated when LaunchServices opens the file (double clicking it in Finder, etc.) as opposed to say, a shell program like vi.

[haihige]

Thanks for the extra information to help troubleshot this. I'm totally fine with the limitation, and understand that not everything will update it. The files I'm mainly interested in tracking it with are media anyway, so they will be opened by double clicking in Finder.

It also doesn't look like the last opened time is changing. It's a static date/time that's random for different files.

atime is set to off for this pool.

# ls -la file.gif
-rw-r--r--  1 haihige haihige 77783 May 29  2023 file.gif
# stat file.gif
11641222150734107805 341799 -rw-r--r-- 1 haihige haihige 0 77783 "Mar 23 12:05:10 2026" "May 29 21:37:03 2023" "May 21 17:44:11 2026" "May 29 21:37:03 2023" 77824 175 0x800 file.gif

file.gif is what the next two sets of logs are for. This is a file where the last opened time is being set (it's not on the root of the share).

This log shows on the second and subsequent times its selected in Finder (not opened).

Jun 29 20:05:23.985836 afpd[49275] {spotlight.c:1379} (debug:Spotlight): afp_spotlight_rpc(vid: 256)
Jun 29 20:05:23.985877 afpd[49275] {spotlight.c:1390} (debug:Spotlight): afp_spotlight_rpc(cmd: 2)
Jun 29 20:05:23.985891 afpd[49275] {spotlight.c:1412} (debug:Spotlight): SPOTLIGHT_CMD_FLAGS: returning 0x0100006b
Jun 29 20:05:23.988687 afpd[49275] {spotlight.c:1379} (debug:Spotlight): afp_spotlight_rpc(vid: 256)
Jun 29 20:05:23.988707 afpd[49275] {spotlight.c:1390} (debug:Spotlight): afp_spotlight_rpc(cmd: 3)
Jun 29 20:05:23.988743 afpd[49275] {spotlight.c:1425} (debug:Spotlight): Spotlight RPC request:
DALLOC_CTX(#1): {
        sl_array_t(#3): {
                sl_array_t(#3): {
                        string: fetchAttributes:forOIDArray:context:
                        uint64_t: 0x305b
                        uint64_t: 0x0000
                }
                sl_array_t(#3): {
                        string: kMDItemPixelHeight
                        string: kMDItemPixelWidth
                        string: kMDItemLastUsedDate
                }
                CNIDs: unkn1: 0xfec, unkn2: 0x6b000080
                        DALLOC_CTX(#1): {
                                uint64_t: 0x03cf
                        }
        }
}

Jun 29 20:05:23.988819 afpd[49275] {spotlight.c:1450} (debug:Spotlight): Spotlight RPC reply dump:
DALLOC_CTX(#1): {
        sl_array_t(#3): {
                uint64_t: 0x0000
                CNIDs: unkn1: 0xfec, unkn2: 0x6b000080
                        DALLOC_CTX(#1): {
                                uint64_t: 0x03cf
                        }
                sl_filemeta_t(#1): {
                        sl_array_t(#2): {
                                nil
                                sl_array_t(#3): {
                                        nil
                                        nil
                                        sl_time_t: 2026-03-23 12:05:10.000000
                                }
                        }
                }
        }
}

Jun 29 20:05:23.988839 afpd[49275] {spotlight_marshalling.c:352} (debug:Spotlight): fmlen: 96

This shows when opening that file.

Jun 29 20:08:03.992779 afpd[64128] {spotlight.c:1379} (debug:Spotlight): afp_spotlight_rpc(vid: 256)
Jun 29 20:08:03.992817 afpd[64128] {spotlight.c:1390} (debug:Spotlight): afp_spotlight_rpc(cmd: 3)
Jun 29 20:08:03.992856 afpd[64128] {spotlight.c:1425} (debug:Spotlight): Spotlight RPC request:
DALLOC_CTX(#1): {
        sl_array_t(#3): {
                sl_array_t(#3): {
                        string: storeAttributes:forOIDArray:context:
                        uint64_t: 0x1064
                        uint64_t: 0x0000
                }
                sl_array_t(#2): {
                        nil
                        sl_dict_t(#2): {
                                string: kMDItemLastUsedDate
                                sl_time_t: 2026-06-29 20:08:03.988924
                        }
                }
                CNIDs: unkn1: 0xadd, unkn2: 0x6b000080
                        DALLOC_CTX(#1): {
                                uint64_t: 0x03cf
                        }
        }
}

Jun 29 20:08:03.992877 afpd[64128] {spotlight.c:1101} (debug:Spotlight): CNID: 975
Jun 29 20:08:03.992936 afpd[64128] {spotlight.c:1450} (debug:Spotlight): Spotlight RPC reply dump:
DALLOC_CTX(#1): {
        sl_array_t(#1): {
                uint64_t: 0x0000
        }
}

Jun 29 20:08:04.127006 afpd[64128] {spotlight.c:1379} (debug:Spotlight): afp_spotlight_rpc(vid: 256)
Jun 29 20:08:04.127036 afpd[64128] {spotlight.c:1390} (debug:Spotlight): afp_spotlight_rpc(cmd: 3)
Jun 29 20:08:04.127069 afpd[64128] {spotlight.c:1425} (debug:Spotlight): Spotlight RPC request:
DALLOC_CTX(#1): {
        sl_array_t(#3): {
                sl_array_t(#3): {
                        string: storeAttributes:forOIDArray:context:
                        uint64_t: 0x1065
                        uint64_t: 0x0000
                }
                sl_array_t(#2): {
                        nil
                        sl_dict_t(#2): {
                                string: kMDItemLastUsedDate
                                sl_time_t: 2026-06-29 20:08:04.123178
                        }
                }
                CNIDs: unkn1: 0xadd, unkn2: 0x6b000080
                        DALLOC_CTX(#1): {
                                uint64_t: 0x03cf
                        }
        }
}

Jun 29 20:08:04.127085 afpd[64128] {spotlight.c:1101} (debug:Spotlight): CNID: 975
Jun 29 20:08:04.127133 afpd[64128] {spotlight.c:1450} (debug:Spotlight): Spotlight RPC reply dump:
DALLOC_CTX(#1): {
        sl_array_t(#1): {
                uint64_t: 0x0000
        }
}

Here's the log for a file at the root of the drive (that doesn't update the last opened time), on second and subsequent selections.

Jun 29 20:06:41.563953 afpd[49275] {spotlight.c:1450} (debug:Spotlight): Spotlight RPC reply dump:
DALLOC_CTX(#1): {
        sl_array_t(#3): {
                uint64_t: 0x0000
                CNIDs: unkn1: 0xfec, unkn2: 0x6b000080
                        DALLOC_CTX(#1): {
                                uint64_t: 0x03c1
                        }
                sl_filemeta_t(#1): {
                        sl_array_t(#2): {
                                nil
                                sl_array_t(#1): {
                                        sl_time_t: 2026-06-27 09:27:39.000000
                                }
                        }
                }
        }
}

Jun 29 20:06:41.563984 afpd[49275] {spotlight_marshalling.c:352} (debug:Spotlight): fmlen: 80

File at the root, opening.

Jun 29 20:20:17.310882 afpd[64128] {spotlight.c:1379} (debug:Spotlight): afp_spotlight_rpc(vid: 256)
Jun 29 20:20:17.310971 afpd[64128] {spotlight.c:1390} (debug:Spotlight): afp_spotlight_rpc(cmd: 3)
Jun 29 20:20:17.311045 afpd[64128] {spotlight.c:1425} (debug:Spotlight): Spotlight RPC request:
DALLOC_CTX(#1): {
        sl_array_t(#3): {
                sl_array_t(#3): {
                        string: storeAttributes:forOIDArray:context:
                        uint64_t: 0x106b
                        uint64_t: 0x0000
                }
                sl_array_t(#2): {
                        nil
                        sl_dict_t(#2): {
                                string: kMDItemLastUsedDate
                                sl_time_t: 2026-06-29 20:20:17.304749
                        }
                }
                CNIDs: unkn1: 0xadd, unkn2: 0x6b000080
                        DALLOC_CTX(#1): {
                                uint64_t: 0x03c1
                        }
        }
}

Jun 29 20:20:17.311085 afpd[64128] {spotlight.c:1101} (debug:Spotlight): CNID: 961
Jun 29 20:20:17.311181 afpd[64128] {spotlight.c:1450} (debug:Spotlight): Spotlight RPC reply dump:
DALLOC_CTX(#1): {
        sl_array_t(#1): {
                uint64_t: 0x0000
        }
}

Jun 29 20:20:17.423232 afpd[64128] {spotlight.c:1379} (debug:Spotlight): afp_spotlight_rpc(vid: 256)
Jun 29 20:20:17.423285 afpd[64128] {spotlight.c:1390} (debug:Spotlight): afp_spotlight_rpc(cmd: 3)
Jun 29 20:20:17.423395 afpd[64128] {spotlight.c:1425} (debug:Spotlight): Spotlight RPC request:
DALLOC_CTX(#1): {
        sl_array_t(#3): {
                sl_array_t(#3): {
                        string: storeAttributes:forOIDArray:context:
                        uint64_t: 0x106c
                        uint64_t: 0x0000
                }
                sl_array_t(#2): {
                        nil
                        sl_dict_t(#2): {
                                string: kMDItemLastUsedDate
                                sl_time_t: 2026-06-29 20:20:17.418956
                        }
                }
                CNIDs: unkn1: 0xadd, unkn2: 0x6b000080
                        DALLOC_CTX(#1): {
                                uint64_t: 0x03c1
                        }
        }
}
Jun 29 20:20:17.423441 afpd[64128] {spotlight.c:1101} (debug:Spotlight): CNID: 961
Jun 29 20:20:17.423528 afpd[64128] {spotlight.c:1450} (debug:Spotlight): Spotlight RPC reply dump:
DALLOC_CTX(#1): {
        sl_array_t(#1): {
                uint64_t: 0x0000
        }
}

Jun 29 20:20:19.125597 afpd[64128] {spotlight.c:1379} (debug:Spotlight): afp_spotlight_rpc(vid: 256)
Jun 29 20:20:19.125664 afpd[64128] {spotlight.c:1390} (debug:Spotlight): afp_spotlight_rpc(cmd: 3)
Jun 29 20:20:19.125735 afpd[64128] {spotlight.c:1425} (debug:Spotlight): Spotlight RPC request:
DALLOC_CTX(#1): {
        sl_array_t(#3): {
                sl_array_t(#3): {
                        string: storeAttributes:forOIDArray:context:
                        uint64_t: 0x106d
                        uint64_t: 0x0000
                }
                sl_array_t(#2): {
                        nil
                        sl_dict_t(#2): {
                                string: kMDItemLastUsedDate
                                sl_time_t: 2026-06-29 20:20:19.120970
                        }
                }
                CNIDs: unkn1: 0xadd, unkn2: 0x6b000080
                        DALLOC_CTX(#1): {
                                uint64_t: 0x03c1
                        }
        }
}

Jun 29 20:20:19.125787 afpd[64128] {spotlight.c:1101} (debug:Spotlight): CNID: 961
Jun 29 20:20:19.125906 afpd[64128] {spotlight.c:1450} (debug:Spotlight): Spotlight RPC reply dump:
DALLOC_CTX(#1): {
        sl_array_t(#1): {
                uint64_t: 0x0000
        }
}

[NJRoadfan]

If ZFS is set with atime = off than it may be that the atime on files won't update at all, even when explicitly set. Additionally, they likely won't update on files that only have read permission per the utimensat() man page.

[haihige]

So the date/time in "Last opened" is based off of atime? If so I can test with atime on, but I'd rather keep it off. I guess I thought it was getting updated by the app that opens the file.

[NJRoadfan]

Yes. Netatalk itself updates atime for the file when a SpotlightRPC request calls storeAttributes:forOIDArray:context:. See:

netatalk/etc/afpd/spotlight.c

Lines 1137 to 1144 in 195bcfb

	} else if ((sl_time = dalloc_value_for_key(query, "DALLOC_CTX", 0, "DALLOC_CTX",
	1, "DALLOC_CTX", 1, "kMDItemLastUsedDate", "sl_time_t"))) {
	struct timespec ts[2] = {{0}};
	ts[0].tv_sec = sl_time->tv_sec;
	ts[0].tv_nsec = sl_time->tv_usec * 1000;
	ts[1].tv_nsec = UTIME_OMIT;
	utimensat(AT_FDCWD, path, ts, 0);
	}

Additionally, the file should have an extended attribute called com.apple.lastuseddate#PS with the same date-time value written to it.

I've actually run into the opposite problem where merely opening the "Get Info..." dialog updates atime. Technically this is correct, but leads to something like Heisenberg's Uncertainty Principle for timestamps, where trying to retrieve the value alters it!