pigeonhole permission errors regarding bin_path
Hi, While trying to use the `sieve_script_bin_path` option to have Pigeonhole auto-create directories for compiled sieve scripts, I ran into some permission issues: "Error: sieve: binary /run/dovecot2/sieve/jasper/84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after.svbin: save: failed to create temporary file: open(/run/dovecot2/sieve/jasper/84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after.svbin.) failed: Permission denied (euid=986(dovemail) egid=985(dovemail) missing +w perm: /run/dovecot2/sieve/jasper, dir owner missing perms)" I'm using `bin_path` like this: `sieve_script_bin_path = "/run/dovecot2/sieve/%{user|username|lower}";` and the permissions of the `sieve` directory are as follows: ``` $ ls -lah sieve total 0 drwxr-xrwx 3 root root 60 Jul 5 13:01 . drwxr-xr-x 10 root root 780 Jul 5 13:00 .. dr-xr-xr-x 2 dovemail dovemail 40 Jul 5 13:01 jasper ``` `strace`ing Dovecot shows that it uses `0555` when creating this directory (but not before setting `umask` to `000`?): ``` 260940 newfstatat(AT_FDCWD</var/vmail/jappie.dev/jasper>, "/run/dovecot2/sieve/jasper", 0x7fff4306af00, 0) = -1 ENOENT (No such file or directory) 260940 umask(000) = 077 260940 mkdir("/run/dovecot2/sieve/jasper", 0555) = 0 260940 umask(077) = 000 ``` I also tried patching Pigeonhole's source to log the value of `mode`: ``` diff --git a/src/lib-sieve/sieve-storage.c b/src/lib-sieve/sieve-storage.c index e68fe39f..4c7a081f 100644 --- a/src/lib-sieve/sieve-storage.c +++ b/src/lib-sieve/sieve-storage.c @@ -887,6 +887,6 @@ int sieve_storage_setup_bin_path(struct sieve_storage *storage, mode_t mode) if (mkdir_parents(bin_path, mode) == 0) { e_debug(storage->event, - "Created directory for binaries: %s", bin_path); + "Created directory for binaries: %s %u", bin_path, mode); return 1; } ``` and this logged `365`, which - if I understand `mode_t` correctly - corresponds to `-wxrw-r-x`: ``` Debug: sieve: storage after: file: Created directory for binaries: /run/dovecot2/sieve/jasper 365 ``` Needless to say, I'm a little confused as to what's going on here - am I missing something or does this look like a Pigeonhole / Dovecot bug? Kind regards, - Jasper Full log: ``` dovecot[260506]: lmtp(260940): Connect from local dovecot[260506]: lmtp(260940): Debug: auth-master: passdb lookup(jasper@jappie.dev): Started passdb lookup dovecot[260506]: lmtp(260940): Debug: auth-master: conn unix:/run/dovecot2/auth-userdb: Connecting dovecot[260506]: lmtp(260940): Debug: auth-master: conn unix:/run/dovecot2/auth-userdb (pid=260501,uid=0): Client connected (fd=14) dovecot[260506]: lmtp(260940): Debug: auth-master: conn unix:/run/dovecot2/auth-userdb (pid=260501,uid=0): auth input: user=jasper@jappie.dev dovecot[260506]: lmtp(260940): Debug: auth-master: passdb lookup(jasper@jappie.dev): auth PASS input: user=jasper@jappie.dev dovecot[260506]: lmtp(260940): Debug: auth-master: passdb lookup(jasper@jappie.dev): Finished passdb lookup (user=jasper@jappie.dev) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: auth-master: userdb lookup(jasper@jappie.dev): Started userdb lookup dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: auth-master: conn unix:/run/dovecot2/auth-userdb (pid=260501,uid=0): auth input: jasper@jappie.dev dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: auth-master: userdb lookup(jasper@jappie.dev): auth USER input: jasper@jappie.dev dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: auth-master: userdb lookup(jasper@jappie.dev): Finished userdb lookup (username=jasper@jappie.dev ) dovecot[260506]: lmtp(260940): Debug: Mailbox <lmtp DATA local>: Mailbox opened dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: Effective uid=986, gid=985, home=/var/vmail/jappie.dev/jasper dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: open(/proc/self/io) failed: Permission denied (euid=986(dovemail) egid=985(dovemail) missing +r perm: /proc/self/io) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: maildir++: root=/var/vmail/jappie.dev/jasper/mail, index=, indexpvt=, control=, inbox=/var/vmail/jappie.dev/jasper/mail, alt= dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: Mailbox <lmtp DATA local>: Adding field hdr.From to cache for the first time (uid=1) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: Mailbox <lmtp DATA local>: Adding field hdr.Message-ID to cache for the first time (uid=1) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: Mailbox <lmtp DATA local>: Adding field hdr.Return-Path to cache for the first time (uid=1) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: Mailbox <lmtp DATA local>: Adding field hdr.Subject to cache for the first time (uid=1) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: Mailbox <lmtp DATA local>: Adding field hdr.To to cache for the first time (uid=1) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: Local delivery started dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: duplicate db: Initialize dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: Pigeonhole version 2.4.0 (1b2d5bb9) initializing dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: storage after: file: Directory for binaries: /run/dovecot2/sieve/jasper dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: storage after: file: Using Sieve script path: /nix/store/84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after.sieve dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: storage after: file: script '84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after': Opened from 'after' dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: Using the following personal Sieve script: after/84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: multi-script: Start execute sequence dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: Opening script 1 of 1 from 'after/84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after' dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: Loading script after/84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: storage after: file: script '84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after': Opened script for reading dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: Script 'after/84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after' successfully compiled dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: storage after: file: Created directory for binaries: /run/dovecot2/sieve/jasper 365 dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: storage after: file: script '84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after': Saving binary to '/run/dovecot2/sieve/jasper/84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after.svbin' dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Error: sieve: binary /run/dovecot2/sieve/jasper/84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after.svbin: save: failed to create temporary file: open(/run/dovecot2/sieve/jasper/84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after.svbin.) failed: Permission denied (euid=986(dovemail) egid=985(dovemail) missing +w perm: /run/dovecot2/sieve/jasper, dir owner missing perms) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: Executing script from 'after/84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after' dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: multi-script: Run script 'after/84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after' dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: Started running script 'after/84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after' dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: Finished running script 'after/84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after' (status=ok, resource usage: no usage recorded) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: multi-script: Execute result dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Executing result (status=ok, commit=no) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Starting execution of actions dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Executing actions dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Executed explicit keep dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Finished executing actions (status=ok, keep=explicit, executed=no) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Finished executing result (no commit, status=ok, keep=yes) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: multi-script: Sequence active dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: multi-script: Finishing sequence (status=ok) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Executing result (status=ok, commit=yes) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Starting execution of actions dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Executing actions dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Finished executing actions (status=ok, keep=implicit, executed=no) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Found deferred keep action dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Execute implicit keep (status=ok) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Start storing into mailbox INBOX dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Executing implicit keep action dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Execute storing into mailbox 'INBOX' dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: Mailbox INBOX: Mailbox opened dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Saving to mailbox 'INBOX' successful so far dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Finished executing implicit keep action (status=ok) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Finalizing actions dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Finished finalizing actions (status=ok, keep=implicit, committed=no) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Finalize implicit keep (status=ok) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Finalize implicit keep action(status=ok, action_status=ok, commit_status=ok) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Commit implicit keep action dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Commit storing into mailbox 'INBOX' dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: stored mail into mailbox 'INBOX' dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Finish implicit keep action dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Finishing actions dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Finished executing result (final, status=ok, keep=yes) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: multi-script: Sequence finished (status=ok, keep=yes) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: multi-script: Destroy dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: storage after: file: script '84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after': Closed script dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: duplicate db: Cleanup dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: Local delivery finished successfully dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: User session is finished dovecot[260506]: lmtp(260940): Disconnect from local: Logged out (state=READY) dovecot[260506]: lmtp(260940): Debug: User session is finished ``` Hi, While trying to use the `sieve_script_bin_path` option to have Pigeonhole auto- create directories for compiled sieve scripts, I ran into some permission issues: "Error: sieve: binary /run/dovecot2/sieve/jasper/ 84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after.svbin: save: failed to create temporary file: open(/run/dovecot2/sieve/jasper/84lkfddk8d88ib7zh3zh6hmy5lrvn54x- after.svbin.) failed: Permission denied (euid=986(dovemail) egid=985(dovemail) missing +w perm: /run/dovecot2/sieve/jasper, dir owner missing perms)" I'm using `bin_path` like this: `sieve_script_bin_path = "/run/dovecot2/sieve/% {user|username|lower}";` and the permissions of the `sieve` directory are as follows: ``` $ ls -lah sieve total 0 drwxr-xrwx 3 root root 60 Jul 5 13:01 . drwxr-xr-x 10 root root 780 Jul 5 13:00 .. dr-xr-xr-x 2 dovemail dovemail 40 Jul 5 13:01 jasper ``` `strace`ing Dovecot shows that it uses `0555` when creating this directory (but not before setting `umask` to `000`?): ``` 260940 newfstatat(AT_FDCWD</var/vmail/jappie.dev/jasper>, "/run/dovecot2/sieve/ jasper", 0x7fff4306af00, 0) = -1 ENOENT (No such file or directory) 260940 umask(000) = 077 260940 mkdir("/run/dovecot2/sieve/jasper", 0555) = 0 260940 umask(077) = 000 ``` I also tried patching Pigeonhole's source to log the value of `mode`: ``` diff --git a/src/lib-sieve/sieve-storage.c b/src/lib-sieve/sieve-storage.c index e68fe39f..4c7a081f 100644 --- a/src/lib-sieve/sieve-storage.c +++ b/src/lib-sieve/sieve-storage.c @@ -887,6 +887,6 @@ int sieve_storage_setup_bin_path(struct sieve_storage *storage, mode_t mode) if (mkdir_parents(bin_path, mode) == 0) { e_debug(storage->event, - "Created directory for binaries: %s", bin_path); + "Created directory for binaries: %s %u", bin_path, mode); return 1; } ``` and this logged `365`, which - if I understand `mode_t` correctly - corresponds to `-wxrw-r-x`: ``` Debug: sieve: storage after: file: Created directory for binaries: /run/ dovecot2/sieve/jasper 365 ``` Needless to say, I'm a little confused as to what's going on here - am I missing something or does this look like a Pigeonhole / Dovecot bug? Kind regards, - Jasper Full log: ``` dovecot[260506]: lmtp(260940): Connect from local dovecot[260506]: lmtp(260940): Debug: auth-master: passdb lookup (jasper@jappie.dev): Started passdb lookup dovecot[260506]: lmtp(260940): Debug: auth-master: conn unix:/run/dovecot2/ auth-userdb: Connecting dovecot[260506]: lmtp(260940): Debug: auth-master: conn unix:/run/dovecot2/ auth-userdb (pid=260501,uid=0): Client connected (fd=14) dovecot[260506]: lmtp(260940): Debug: auth-master: conn unix:/run/dovecot2/ auth-userdb (pid=260501,uid=0): auth input: user=jasper@jappie.dev dovecot[260506]: lmtp(260940): Debug: auth-master: passdb lookup (jasper@jappie.dev): auth PASS input: user=jasper@jappie.dev dovecot[260506]: lmtp(260940): Debug: auth-master: passdb lookup (jasper@jappie.dev): Finished passdb lookup (user=jasper@jappie.dev) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: auth-master: userdb lookup(jasper@jappie.dev): Started userdb lookup dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: auth-master: conn unix:/run/dovecot2/auth-userdb (pid=260501,uid=0): auth input: jasper@jappie.dev dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: auth-master: userdb lookup(jasper@jappie.dev): auth USER input: jasper@jappie.dev dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: auth-master: userdb lookup(jasper@jappie.dev): Finished userdb lookup (username=jasper@jappie.dev ) dovecot[260506]: lmtp(260940): Debug: Mailbox <lmtp DATA local>: Mailbox opened dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: Effective uid=986, gid=985, home=/var/vmail/jappie.dev/jasper dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: open(/proc/self/io) failed: Permission denied (euid=986(dovemail) egid=985(dovemail) missing +r perm: /proc/self/io) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: maildir++: root=/var/vmail/jappie.dev/jasper/mail, index=, indexpvt=, control=, inbox=/var/vmail/jappie.dev/jasper/mail, alt= dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: Mailbox <lmtp DATA local>: Adding field hdr.From to cache for the first time (uid=1) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: Mailbox <lmtp DATA local>: Adding field hdr.Message-ID to cache for the first time (uid=1) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: Mailbox <lmtp DATA local>: Adding field hdr.Return-Path to cache for the first time (uid=1) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: Mailbox <lmtp DATA local>: Adding field hdr.Subject to cache for the first time (uid=1) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: Mailbox <lmtp DATA local>: Adding field hdr.To to cache for the first time (uid=1) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: Local delivery started dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: duplicate db: Initialize dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: Pigeonhole version 2.4.0 (1b2d5bb9) initializing dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: storage after: file: Directory for binaries: /run/dovecot2/sieve/ jasper dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: storage after: file: Using Sieve script path: /nix/store/ 84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after.sieve dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: storage after: file: script '84lkfddk8d88ib7zh3zh6hmy5lrvn54x- after': Opened from 'after' dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: Using the following personal Sieve script: after/ 84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: multi-script: Start execute sequence dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: Opening script 1 of 1 from 'after/ 84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after' dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: Loading script after/84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: storage after: file: script '84lkfddk8d88ib7zh3zh6hmy5lrvn54x- after': Opened script for reading dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: Script 'after/84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after' successfully compiled dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: storage after: file: Created directory for binaries: /run/ dovecot2/sieve/jasper 365 dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: storage after: file: script '84lkfddk8d88ib7zh3zh6hmy5lrvn54x- after': Saving binary to '/run/dovecot2/sieve/jasper/ 84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after.svbin' dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Error: sieve: binary /run/dovecot2/sieve/jasper/ 84lkfddk8d88ib7zh3zh6hmy5lrvn54x-after.svbin: save: failed to create temporary file: open(/run/dovecot2/sieve/jasper/84lkfddk8d88ib7zh3zh6hmy5lrvn54x- after.svbin.) failed: Permission denied (euid=986(dovemail) egid=985(dovemail) missing +w perm: /run/dovecot2/sieve/jasper, dir owner missing perms) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: Executing script from 'after/84lkfddk8d88ib7zh3zh6hmy5lrvn54x- after' dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: multi-script: Run script 'after/84lkfddk8d88ib7zh3zh6hmy5lrvn54x- after' dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: Started running script 'after/84lkfddk8d88ib7zh3zh6hmy5lrvn54x- after' dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: Finished running script 'after/84lkfddk8d88ib7zh3zh6hmy5lrvn54x- after' (status=ok, resource usage: no usage recorded) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: multi-script: Execute result dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Executing result (status=ok, commit=no) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Starting execution of actions dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Executing actions dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Executed explicit keep dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Finished executing actions (status=ok, keep=explicit, executed=no) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Finished executing result (no commit, status=ok, keep=yes) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: multi-script: Sequence active dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: multi-script: Finishing sequence (status=ok) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Executing result (status=ok, commit=yes) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Starting execution of actions dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Executing actions dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Finished executing actions (status=ok, keep=implicit, executed=no) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Found deferred keep action dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Execute implicit keep (status=ok) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Start storing into mailbox INBOX dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Executing implicit keep action dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Execute storing into mailbox 'INBOX' dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: Mailbox INBOX: Mailbox opened dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Saving to mailbox 'INBOX' successful so far dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Finished executing implicit keep action (status=ok) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Finalizing actions dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Finished finalizing actions (status=ok, keep=implicit, committed=no) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Finalize implicit keep (status=ok) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Finalize implicit keep action(status=ok, action_status=ok, commit_status=ok) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Commit implicit keep action dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Commit storing into mailbox 'INBOX' dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: stored mail into mailbox 'INBOX' dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Finish implicit keep action dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Finishing actions dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: msgid=<E62D66EA-D095-4EBC-AFFE-640FB6824F45@jappie.dev>: Finished executing result (final, status=ok, keep=yes) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: multi-script: Sequence finished (status=ok, keep=yes) dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: multi-script: Destroy dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: sieve: storage after: file: script '84lkfddk8d88ib7zh3zh6hmy5lrvn54x- after': Closed script dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: duplicate db: Cleanup dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: Local delivery finished successfully dovecot[260506]: lmtp(jasper@jappie.dev)<260940><3P0ZDyQGaWhM+wMAbxW+ag>: Debug: User session is finished dovecot[260506]: lmtp(260940): Disconnect from local: Logged out (state=READY) dovecot[260506]: lmtp(260940): Debug: User session is finished ```
On 6. Jul 2025, at 16:08, jasper@jappie.dev wrote:
- "Created directory for binaries: %s %u", bin_path, mode);
and this logged
365
, which - if I understandmode_t
correctly - corresponds to-wxrw-r-x
:Debug: sieve: storage after: file: Created directory for binaries: /run/dovecot2/sieve/jasper 365
FWIW, this prints the mode as decimal, and decimal 365 is octal 555 (r-xr-xr-x). So the permissions shown in strace and the permissions printed from your debug line match up. You can use ‘%o’ instead of ‘%u’ to get the octal representation directly.
Cheers, Katalin
participants (2)
-
jasper@jappie.dev
-
Katalin Rebhan