[horde] [whups]: error on script pipe in postfix

Mon Mar 12 14:25:16 UTC 2018

Am 12.03.2018 um 14:46 schrieb Patrick Boutilier:
> On 03/12/2018 10:04 AM, Carsten wrote:
>>
>>
>> Am 12.03.2018 um 13:36 schrieb Patrick Boutilier:
>>> On 03/11/2018 08:52 PM, Carsten wrote:
>>>>
>>>>
>>>> Am 11.03.2018 um 23:57 schrieb Jan Schneider:
>>>>>
>>>>> Zitat von Carsten <horde-groupware at familie-lahme.de>:
>>>>>
>>>>>> Am 11.03.2018 um 21:05 schrieb Jan Schneider:
>>>>>>>
>>>>>>> Zitat von Carsten <horde-groupware at familie-lahme.de>:
>>>>>>>
>>>>>>>> Am 11.03.2018 um 13:07 schrieb Carsten:
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> Am 11.03.2018 um 12:35 schrieb Carsten:
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> Am 10.03.2018 um 21:00 schrieb Jan Schneider:
>>>>>>>>>>>
>>>>>>>>>>> Zitat von Carsten <horde-groupware at familie-lahme.de>:
>>>>>>>>>>>
>>>>>>>>>>>> Am 10.03.2018 um 11:20 schrieb Jan Schneider:
>>>>>>>>>>>>>
>>>>>>>>>>>>> Zitat von Carsten <horde-groupware at familie-lahme.de>:
>>>>>>>>>>>>>
>>>>>>>>>>>>>> Am 09.03.2018 um 11:38 schrieb Jan Schneider:
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Zitat von Carsten <horde-groupware at familie-lahme.de>:
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> Hi all,
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> I try the set up whups with automated ticket generation 
>>>>>>>>>>>>>>>> from mails.
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> my postfix sends the incoming mail to the pipe, but 
>>>>>>>>>>>>>>>> returns such an error:
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> Mar  8 12:40:38 derdapp004 postfix/local[30799]: 
>>>>>>>>>>>>>>>> 04C7040C4C: to=<whups at localhost>, 
>>>>>>>>>>>>>>>> orig_to=<whups@[mydn.tdl]>, relay=local, delay=0.58, 
>>>>>>>>>>>>>>>> delays=0.09/0.04/0/0.45, dsn=5.3.0, status=bounced 
>>>>>>>>>>>>>>>> (Command died with status 255: 
>>>>>>>>>>>>>>>> "/usr/bin/whups-mail-filter -g". Command output: PHP 
>>>>>>>>>>>>>>>> Warning: 
>>>>>>>>>>>>>>>> require_once(/usr/share/php/www/horde/whups/lib/Application.php): 
>>>>>>>>>>>>>>>> failed to open stream: No such file or directory in 
>>>>>>>>>>>>>>>> /usr/bin/whups-mail-filter on line 73 PHP Fatal error: 
>>>>>>>>>>>>>>>> require_once(): Failed opening required 
>>>>>>>>>>>>>>>> '/usr/share/php/www/horde/whups/lib/Application.php' 
>>>>>>>>>>>>>>>> (include_path='.:/usr/share/php:/usr/share/pear') in 
>>>>>>>>>>>>>>>> /usr/bin/whups-mail-filter on line 73 )
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> If I pipe with the local user (root) from the command 
>>>>>>>>>>>>>>>> line, it works perfect.
>>>>>>>>>>>>>>>> I guess it is about a missing environment o.s.
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> Can somebody advice, pls?
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> br
>>>>>>>>>>>>>>>> Carsten
>>>>>>>>>>>>>>>
>> [..snipped out some parts, because got size warning from mailinglist..]
>>>>>>>>>> Checked file permissions. As described above:
>>>>>>>>>>
>>>>>>>>>> ###################
>>>>>>>>>> #
>>>>>>>>>> root at derdapp004 ~www/horde/whups/lib # pwd
>>>>>>>>>> /var/www/horde/whups/lib
>>>>>>>>>> root at derdapp004 ~www/horde/whups/lib # ll Application.php
>>>>>>>>>> -rwxr--r-x 1 www-data root 9169 Mar  7 11:33 Application.php
>>>>>>>>>> ##
>>>>>>>>>> ##################
>>>>>>>>>>
>>>>>>>>>> Let's check, what would be the output of a call of that file:
>>>>>>>>>>
>>>>>>>>>> #################
>>>>>>>>>> ##
>>>>>>>>>> root at derdapp004 ~www/horde/whups/lib # php -f Application.php
>>>>>>>>>> root at derdapp004 ~www/horde/whups/lib #
>>>>>>>>>> ##
>>>>>>>>>> #################
>>>>>>>>>>
>>>>>>>>>> Now with postfix:
>>>>>>>>>>
>>>>>>>>>> #################
>>>>>>>>>> ##
>>>>>>>>>> root at derdapp004 ~www/horde # sudo -u postfix php -f 
>>>>>>>>>> /var/www/horde/whups/lib/Application.php
>>>>>>>>>> Could not open input file: 
>>>>>>>>>> /var/www/horde/whups/lib/Application.php
>>>>>>>>>> #
>>>>>>>>>> ##################
>>>>>>>>>>
>>>>>>>>>> Now I did a more intense check of the permissions, using
>>>>>>>>>>
>>>>>>>>>> ##############
>>>>>>>>>> ##
>>>>>>>>>> root at derdapp004 ~www/horde/whups/lib # sudo -u postfix ls 
>>>>>>>>>> /var/www/horde/whups/lib
>>>>>>>>>> ls: cannot access /var/www/horde/whups/lib: Permission denied
>>>>>>>>>> root at derdapp004 ~www/horde/whups/lib # cd /var/www/horde
>>>>>>>>>> root at derdapp004 ~www/horde # ll
>>>>>>>>>> total 136
>>>>>>>>>> [...snipp...]
>>>>>>>>>> drwxr--r-- 13 www-data root  4096 Mar  7 11:33 whups
>>>>>>>>>> ##
>>>>>>>>>> ##############
>>>>>>>>>>
>>>>>>>>>> and bingo, a thing, I will never understand in the LX 
>>>>>>>>>> permission context: You need execute to enter a directory
>>>>>>>>>> Thinking about RBAC I solved it with this:
>>>>>>>>>> 1st: create a group "www-horde"
>>>>>>>>>> 2nd: put user postfix into that group
>>>>>>>>>> 3rd: do a "chown -R www-data:www-horde /var/www/horde"
>>>>>>>>>> 4th: do a "chmod -R 750 /var/www/horde"
>>>>>>>>>> 5th: do another test:
>>>>>>>>>>
>>>>>>>>>> #################
>>>>>>>>>> ##
>>>>>>>>>> root at derdapp004 ~www/horde # sudo -u postfix /tmp/testmail
>>>>>>>>>> [clearscreen]
>>>>>>>>>> Hi, my name is postfix
>>>>>>>>>> root at derdapp004 ~www/horde #
>>>>>>>>>> ##
>>>>>>>>>> #################
>>>>>>>>>>
>>>>>>>>>> Ticket created!! And now: be happy.... ;-)
>>>>>>>>>>
>>>>>>>>>> Thanks for You patients and help!!
>>>>>>>>>>
>>>>>>>>>> br
>>>>>>>>>> Carsten
>>>>>>>>>
>>>>>>>>> ok, back, where we have started. I've forgotten the test using 
>>>>>>>>> the mail:
>>>>>>>>> #######################
>>>>>>>>> ##
>>>>>>>>>
>>>>>>>>> <whups at localhost> (expanded from <whups@[mydn.tld]>): Command 
>>>>>>>>> died with
>>>>>>>>>     status 255: "/usr/bin/whups-mail-filter -g -a 
>>>>>>>>> carsten@[mydn.tld] -Q
>>>>>>>>>     5". Command output: PHP Warning:
>>>>>>>>> require_once(/var/www/horde/whups/lib/Application.php): failed 
>>>>>>>>> to open
>>>>>>>>>     stream: Permission denied in /usr/bin/whups-mail-filter on 
>>>>>>>>> line 73 PHP
>>>>>>>>>     Fatal error:  require_once(): Failed opening required
>>>>>>>>>     '/var/www/horde/whups/lib/Application.php'
>>>>>>>>> (include_path='.:/usr/share/php:/usr/share/pear') in
>>>>>>>>>     /usr/bin/whups-mail-filter on line 73
>>>>>>>>>
>>>>>>>>> ##
>>>>>>>>> #######################
>>>>>>>>>
>>>>>>>>> *BöseFlüche*
>>>>>>>>>
>>>>>>>>> What else have I missed?
>>>>>>>>>
>>>>>>>>> br
>>>>>>>>> Carsten
>>>>>>>>
>>>>>>>> I did some more research and found that:
>>>>>>>> "...
>>>>>>>> postfix/main.cf
>>>>>>>> default_privs (default: nobody)
>>>>>>>> The default rights used by the local(8) delivery agent for 
>>>>>>>> delivery to external file or command. These rights are used 
>>>>>>>> when delivery is requested from an aliases(5) file that is 
>>>>>>>> owned by root, or when delivery is done on behalf of root. DO 
>>>>>>>> NOT SPECIFY A PRIVILEGED USER OR THE POSTFIX OWNER.
>>>>>>>> ..."
>>>>>>>>
>>>>>>>> I added two lines to the whups-mail-filter like that:
>>>>>>>> "...
>>>>>>>> <?php
>>>>>>>> $shellex = shell_exec("logger INFO $(whoami)");
>>>>>>>> echo $shellex;
>>>>>>>> ..."
>>>>>>>>
>>>>>>>> Which returned this in the syslog:
>>>>>>>> "..
>>>>>>>> Mar 11 13:25:58 derdapp004 logger: INFO nobody
>>>>>>>> ..."
>>>>>>>>
>>>>>>>> So, we are back to the permissions.
>>>>>>>>
>>>>>>>> 1st: create a new user "postfix-pipe"
>>>>>>>> 2nd: add it to the group "www-horde".
>>>>>>>> 3rd: add "default_privs = postfix-pipe" to the main.cf
>>>>>>>> 4th: do a postmap main.cf and a postfix reload
>>>>>>>> 5th: do a command line check:
>>>>>>>> ##############################
>>>>>>>> ##
>>>>>>>> root at derdapp004 /etc # sudo -u postfix-pipe php -f 
>>>>>>>> /var/www/horde/whups/lib/Application.php
>>>>>>>> root at derdapp004 /etc #
>>>>>>>> ##
>>>>>>>> ##############################
>>>>>>>> => works!
>>>>>>>>
>>>>>>>> 6th: do a mail check:
>>>>>>>> "...
>>>>>>>> Mar 11 13:54:39 derdapp004 logger: INFO postfix-pipe
>>>>>>>> Mar 11 13:54:40 derdapp004 postfix/local[32191]: A2D55415CC: 
>>>>>>>> to=<whups at localhost>, orig_to=<whups@[mydn.tld]>, relay=local, 
>>>>>>>> delay=0.61, delays=0.08/0.04/0/0.5, dsn=5.3.0, status=bounced 
>>>>>>>> (Command died with status 255: "/usr/bin/whups-mail-filter -g 
>>>>>>>> -a carsten@[mydn.tld] -Q 5". Command output: PHP Warning: 
>>>>>>>> require_once(/var/www/horde/whups/lib/Application.php): failed 
>>>>>>>> to open stream: Permission denied in /usr/bin/whups-mail-filter 
>>>>>>>> on line 76 PHP Fatal error: require_once(): Failed opening 
>>>>>>>> required '/var/www/horde/whups/lib/Application.php' 
>>>>>>>> (include_path='.:/usr/share/php:/usr/share/pear') in 
>>>>>>>> /usr/bin/whups-mail-filter on line 76 )
>>>>>>>> ..."
>>>>>>>> => FAILS!!
>>>>>>>>
>>>>>>>> now I am totaly off.......
>>>>>>>
>>>>>>> Did you check the permissions of all parent directories too?
>>>>>>>
>>>>>> I think, I did, but let's walk through:
>>>>>> Toplevel "var" looks ok (other = r and x):
>>>>>> ###
>>>>>> root at derdapp004 ~www # cd /
>>>>>> root at derdapp004 / # ll
>>>>>> [...snip...]
>>>>>> drwxr-xr-x  14 root  root       4096 May  3  2017 var
>>>>>> ###
>>>>>>
>>>>>> Step into /var and check "www".
>>>>>> looks good, too.(other = r and x):
>>>>>> ###
>>>>>> root at derdapp004 / # cd var
>>>>>> root at derdapp004 /var # ll
>>>>>> [...snip...]
>>>>>> drwxr-xr-x  4 root  root  4096 May  6  2017 www
>>>>>> ###
>>>>>>
>>>>>> Now into www to check "horde".
>>>>>> From here we use group permission (www-horde = r and x)
>>>>>> ###
>>>>>> oot at derdapp004 /var # cd www
>>>>>> root at derdapp004 ~www # ll
>>>>>> drwxr-x--- 24 www-data www-horde 4096 Mar  7 11:33 horde
>>>>>> ###
>>>>>>
>>>>>> Next below horde is "whups":
>>>>>> ###
>>>>>> root at derdapp004 ~www # cd horde :(
>>>>>> root at derdapp004 ~www/horde # ll
>>>>>> [...snip...]
>>>>>> drwxr-x--- 13 www-data www-horde  4096 Mar  7 11:33 whups
>>>>>> ###
>>>>>>
>>>>>> Subfolder "lib":
>>>>>> ###
>>>>>> oot at derdapp004 ~www/horde # cd whups
>>>>>> root at derdapp004 ~www/horde/whups # ll
>>>>>> [..snip..]
>>>>>> drwxr-x--- 14 www-data www-horde 4096 Mar  7 11:33 lib
>>>>>> ###
>>>>>>
>>>>>> and last but nor least the file itself:
>>>>>> ###
>>>>>> root at derdapp004 ~www/horde/whups # cd lib
>>>>>> root at derdapp004 ~www/horde/whups/lib # ll
>>>>>> [...snip...]
>>>>>> -rwxr-x--- 1 www-data www-horde  9232 Mar 11 18:55 Application.php
>>>>>> ###
>>>>>>
>>>>>> I do not see any error from that point of view.
>>>>>>
>>>>>> If I do a "chmod -R 777 *" through the horde structure, it works.
>>>>>> I have added the "whoami" lines to the "Application.php" and it 
>>>>>> returns "postfix-pipe" if executed successful.
>>>>>>
>>>>>> I already checked for apparmor and selinux, but last is not 
>>>>>> active and first is only configured for mysql.
>>>>>> The server has been rebooted meanwhile, too, just to make sure 
>>>>>> the new user/group objects are loaded, but no change.
>>>>>> At the moment I am totally out of ideas, and a "777" is not 
>>>>>> really acceptable from my perspective.
>>>>>>
>>>>>> Any idea, how to do a "strace" on whups-mail-filter?!
>>>>>>
>>>>>> br
>>>>>> Carsten
>>>>>
>>>>> strace php whups-mail-filter
>>>>>
>>>> After tricking around, with how to implement this in the alias 
>>>> pipe, I worked out this simple solution:
>>>>
>>>> "...
>>>> whups:   "|strace -o /tmp/trace.log /usr/bin/whups-mail-filter -g 
>>>> -a carsten@[mydn.tld] -Q 5"
>>>> ..."
>>>>
>>>> sending a mail to the pipe creates some output including this part:
>>>>
>>>> ####################
>>>> ###
>>>> [...snip...]
>>>> gettimeofday({1520811096, 605233}, NULL) = 0
>>>> lstat64("/var/www/horde/whups/lib/Application.php", 0xbec64008) = 
>>>> -1 EACCES (Permission denied)
>>>> gettimeofday({1520811096, 605766}, NULL) = 0
>>>> lstat64("/var/www/horde/whups/lib/Application.php", 0xbec63f18) = 
>>>> -1 EACCES (Permission denied)
>>>> gettimeofday({1520811096, 606180}, NULL) = 0
>>>> lstat64("/var/www/horde/whups/lib/Application.php", 0xbec65fe0) = 
>>>> -1 EACCES (Permission denied)
>>>> lstat64("/var/www/horde/whups/lib", 0xbec65ee0) = -1 EACCES 
>>>> (Permission denied)
>>>> lstat64("/var/www/horde/whups", 0xbec65df0) = -1 EACCES (Permission 
>>>> denied)
>>>> lstat64("/var/www/horde", {st_mode=S_IFDIR|0770, st_size=4096, 
>>>> ...}) = 0
>>>> lstat64("/var/www", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
>>>> lstat64("/var", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
>>>> open("/var/www/horde/whups/lib/Application.php", 
>>>> O_RDONLY|O_LARGEFILE) = -1 EACCES (Permission denied)
>>>> [...snip...]
>>>> ###
>>>> ####################
>>>>
>>>> Well nothing surprising in the first view.
>>>> If I run a simple command line like
>>>> "...
>>>> sudo -u postfix-pipe strace -o /tmp/trace1.log 
>>>> /usr/bin/whups-mail-filter
>>>> ..."
>>>>
>>>> This is the output:
>>>>
>>>> ####################
>>>> ###
>>>> [...snip...]
>>>> ettimeofday({1520812051, 622266}, NULL) = 0
>>>> lstat64("/var/www/horde/whups/lib/Application.php", 
>>>> {st_mode=S_IFREG|0770, st_size=9232, ...}) = 0
>>>> lstat64("/var/www/horde/whups/lib", {st_mode=S_IFDIR|0770, 
>>>> st_size=4096, ...}) = 0
>>>> lstat64("/var/www/horde/whups", {st_mode=S_IFDIR|0770, 
>>>> st_size=4096, ...}) = 0
>>>> lstat64("/var/www/horde", {st_mode=S_IFDIR|0770, st_size=4096, 
>>>> ...}) = 0
>>>> lstat64("/var/www", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
>>>> lstat64("/var", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
>>>> gettimeofday({1520812051, 624126}, NULL) = 0
>>>> open("/var/www/horde/whups/lib/Application.php", 
>>>> O_RDONLY|O_LARGEFILE) = 4
>>>> [...snip...]
>>>> ###
>>>> ####################
>>>>
>>>> Do You see the different values in the lstat64? Where do they come 
>>>> from?
>>>> Somebody more familiar with strace output here?
>>>>
>>>
>>> Are you sure that postfix-pipe is the correct user? As far as I can 
>>> tell "default_privs" only affects local deliveries, not pipe. Try 
>>> changing to
>>>
>>> whups:   "|whoami > /tmp/post-user && strace -o /tmp/trace.log 
>>> /usr/bin/whups-mail-filter -g -a carsten@[mydn.tld] -Q 5"
>>>
>>>
>>> and then checking the contents of /tmp/post-user .
>>>
>>>
>> Hi,
>> I know, the thread has gotten very long and hard to read, but I 
>> checked this.
>> This is the current heading of the "whups-mail-filter":
>>
>> ########################
>> ##
>> #!/usr/bin/php
>> <?php
>> $shellex = shell_exec("logger INFO whoami: $(whoami)");
>> $shellex = shell_exec("logger INFO who am i: $(who am i)");
>> $shellex = shell_exec("touch /tmp/hallowelt.ini");
>> ##
>> ########################
>>
>> The output in the syslog, if triggered using postfix:
>> #########################
>> ##
>> Mar 12 13:35:27 derdapp004 logger: INFO whoami: postfix-pipe
>> Mar 12 13:35:27 derdapp004 logger: INFO who am i:
>> ##
>> ##########################
>>
>> The file:
>> #################
>> ##
>> ll /tmp/hallo*
>> -rw------- 1 postfix-pipe postfix-pipe      0 Mar 12 13:35 hallowelt.ini
>> ##
>> #################
>>
>> No doubt, that user "postfix-pipe" is in use.
>>
>> br
>> Carsten
>
>
>
> lstat64("/var/www/horde/whups", 0xbec65df0) = -1 EACCES (Permission 
> denied)
>
>
> suggests otherwise though. You said 777 made things work. Can you try 
> giving the same right as postfix-pipe to the postfix and nobody users 
> for a test?
>
I reworked the permissions on the tree as follows:
/ : drwxr-xr-x  16 root  root /var
/var : drwxr-xr-x  4 root  root  4096 May  6  2017 www
/var/www : drwxr-xr-x 24 www-data www-horde 4096 Mar  7 11:33 horde
/var/www/horde : drwxr-xr-x 13 www-data www-horde  4096 Mar  7 11:33 whups
/var/www/horde/whups : drwxr-xr-x 14 www-data www-horde 4096 Mar  7 
11:33 lib
/var/www/horde/whups/lib : -rwxr-x--- 1 postfix-pipe www-horde  9232 Mar 
11 18:55 Application.php

Pointing out the chances: set 755 from "var" down to "lib" and changed 
owner of "Application.php" to "postfix-pipe".

=>> This version works.

If I set the owner of "Application.php" back to "www-data" it fails again.
Just to make sure, the group member ship is correct:
########################
##
root at derdapp004 ~www/horde/whups/lib # groups postfix-pipe :(
postfix-pipe : postfix-pipe www-horde
##
########################

It seems to ignore the group member ship, if triggered by postfix aliases.