Deleting user with CMD_API_SELECT_USERS sometimes has empty result

kristian

Verified User
Joined
Nov 4, 2005
Messages
436
Location
Norway
In one of my scripts I delete users using the CMD_API_SELECT_USERS call (using the httpsocket.php library). Recently I've encountered a few situations where the deletion successfully completes with no special information in any DirectAdmin logs, but the result is empty.

Here's the function that does the deletion, with a print_r for debugging purposes:

PHP:
function deleteAccount($sock, $strUser) {
    $sock->set_method('POST');
    $sock->query('/CMD_API_SELECT_USERS',
        array(
            'confirmed' => 'Confirm',
            'delete' => 'yes',
            'select0' => $strUser,
        ));
    $resDeleteAccount = $sock->fetch_parsed_body();
    print_r($resDeleteAccount);
    if (isset($resDeleteAccount['error']) && $resDeleteAccount['error'] === '0') {
        printAndLog("Deletion of " . $strUser . " has been completed.\n");
    }
    else {
        printAndLog("There was a problem deleting the user " . $strUser . ": " . $resDeleteAccount['text'] . "\n");
        printAndLog("Details: " . $resDeleteAccount['details'] . "\n");
    }
}

The print_r shows this output:
PHP:
Array
(
)

I have not yet done any in depth debugging of this due to the fact that it's not really reproducible from what I can tell (it does not happen with all accounts). I was wondering if anyone had experienced similar issues and/or had any idea what might be causing this behaviour?
 
After several user deletions, I managed to trigger the error while having directadmin running in debug mode. Everything looks the same, except for this line:

Code:
File ./data/users/admin/users.list has been written to after this process read it.  Not going to overwrite it. This read timestamp=1621340435, before-write timestamp=1621340436

Here's the (almost) full output from ./directadmin b2000 from a normal deletion with a proper result returned:

Code:
Command::doCommand(/CMD_API_SELECT_USERS)
Command::delete_in_background: 1 accounts to be deleted in foreground: 52 <= 10240
Reseller::deleteUsers: Deleting account '<redacted-user>' ...
Tally::get_bandwidth_breakdown(ConfigFile &data, int cache=1, int year=0, int month=0): file=./data/users/<redacted-user>/bandwidth.tally.cache
IP::remove_list_from_domain_ips: should_add_domain_to_domainips=0
IP::add_list_to_helo_data: should_add_domain_to_domainips=0
Ftp::removeVirtualHost()
IP::removeFromIP(<redacted-ip>, skip_if_owned=0)
Database::set_mysqld_ver: got connection version: 10.2.23-MariaDB
Database::set_mysqld_ver: found vesion 10.2.23 mariadb=1
Database::clear_system_account_access_hosts(MYSQL &conf, db='<redacted-user>_forum'): query:
'DELETE FROM mysql.user                                                                         WHERE user='<redacted-user>' AND host NOT IN                                                                           (SELECT host FROM mysql.db WHERE (db!='<redacted-user>_forum' AND db!='<redacted-user>\_forum') AND (db LIKE '<redacted-user>_%' OR db LIKE '<redacted-user>\_%'))'
killUserProcess: non-zero response from killall process for '<redacted-user>' with exit code 1:
User::destroy: unlock_actions for <redacted-user>
User::destroy:<redacted-user>: DONE
User <redacted-user> removed by admin

Dynamic(api=1, error=0):
        text='Users deleted'
        result='User <redacted-user> Removed<br>
User removed from SSH<br>
<redacted-domain>'s config files have been removed<br>
<br>
Users's domains directory removed.<br>
<br>
Unix User removed from the server<br>
User's config files deleted<br>
User's data directory removed.<br>
Removed user from admin's list<br>
<br>
<br>
'
Command::doCommand(/CMD_API_SELECT_USERS) : finished
Command::run: finished /CMD_API_SELECT_USERS

The result returned and printed with the print_r mentioned earlier, was this:

Code:
Array                                                       
(                                                                   
    [error] => 0                                                                                   
    [text] => Users deleted                                                                       
    [details] => User <redacted-user> Removed<br>                             
User removed from SSH<br>                                   
<redacted-domain>'s config files have been removed<br>                                                 
<br>                                                                                             
Users's domains directory removed.<br>                                                   
<br>                                                       
Unix User removed from the server<br>                                                         
User's config files deleted<br>                                                   
User's data directory removed.<br>                                                                             
Removed user from admin's list<br>                                                                             
<br>                                                                                               
<br>                                                                 
                                                                                            
)

And this is the output from the API call that returned an empty result:

Code:
Command::doCommand(/CMD_API_SELECT_USERS)
Command::delete_in_background: 1 accounts to be deleted in foreground: 474 <= 10240
Reseller::deleteUsers: Deleting account '<redacted-user>' ...
Tally::get_bandwidth_breakdown(ConfigFile &data, int cache=1, int year=0, int month=0): file=./data/users/<redacted-user>/bandwidth.tally.cache
IP::remove_list_from_domain_ips: should_add_domain_to_domainips=0
IP::add_list_to_helo_data: should_add_domain_to_domainips=0
Ftp::removeVirtualHost()
IP::removeFromIP(<redacted-ip>, skip_if_owned=0)
Database::set_mysqld_ver: got connection version: 10.2.23-MariaDB
Database::set_mysqld_ver: found vesion 10.2.23 mariadb=1
killUserProcess: non-zero response from killall process for '<redacted-user>' with exit code 1:
User::destroy: unlock_actions for <redacted-user>
User::destroy:<redacted-user>: DONE
User <redacted-user> removed by admin

Dynamic(api=1, error=0):
        text='Users deleted'
        result='User <redacted-user> Removed<br>
User removed from SSH<br>
<redacted-domain>'s config files have been removed<br>
<br>
Users's domains directory removed.<br>
<br>
Unix User removed from the server<br>
User's config files deleted<br>
User's data directory removed.<br>
Removed user from admin's list<br>
<br>
<br>
'
Command::doCommand(/CMD_API_SELECT_USERS) : finished
File ./data/users/admin/users.list has been written to after this process read it.  Not going to overwrite it. This read timestamp=1621340435, before-write timestamp=1621340436
Command::run: finished /CMD_API_SELECT_USERS

That extra line in this output isn't reported as an error, so I'm not sure this is the cause, but it's the only difference I can see between the runs. Could there be some kind of bug here, causing the return value to be emptied?
 
You may want to test the API with postman for debugging.
 
Not sure I would get any more information from that, unless I've misunderstood what postman does. This looks like a bug inside DirectAdmin somewhere, handling the API call.
 
Looking in the httpsocket code, the fetch_parsed_body runs parse_str on the output.
If that function fails, the actual body might be there with "something", but still returning nothing.

For debug purposes, try echo'ing the call to
Code:
echo $sock->fetch_body()
which is the raw output, which may shed more info as to what's going on (or even $sock->fetch_result(), which is the entire output with headers... I believe)
 
Good point. I updated my deleteAccount() function to now print additional data:

PHP:
    $resDeleteAccount = $sock->fetch_parsed_body();
    print("\n\$resDeleteAccount (->fetch_parsed_body())\n");
    var_dump($resDeleteAccount);
    print("\n->get_status_code()\n");
    var_dump($sock->get_status_code());
    print("\n->fetch_result()\n");
    var_dump($sock->fetch_result());
    print("\n->fetch_header()\n");
    var_dump($sock->fetch_header());
    print("\n->fetch_body()\n");
    var_dump($sock->fetch_body());

This resulted in the following output for a failure situation:

Code:
$resDeleteAccount (->fetch_parsed_body())
array(0) {
}

->get_status_code()
int(200)

->fetch_result()
bool(false)

->fetch_header()
array(1) {
  [0]=>
  string(0) ""
}

->fetch_body()
bool(false)
 
This is still an issue for me. Has nobody else encountered similar problems? It makes it really hard to trust the results of API calls. :(
 
If we see the "Dynamic" output, then DA is "sending" the output.
Why it's not making it to the script is unknown..
Running with debug level "23" is specific to the Send class, in case that's gives any extra output.

I'm not sure if it's possibly time related? Eg: a larger account might take longer to delete.
If that is the case, you could lower your directadmin.conf setting:
Code:
background_delete_size=10240
to something so low that it would almost always force it to the background.. but if DA itself was generating a timeout, you'd see it.. so would only apply if there's some sort of timing issue with something down the pipe.
If it's some but with pipes, then the above might still work, as the bulk of the work would be done elsewhere... but any errors wouldn't be reported to the API since the action would be done in the background (you'd get a Message System notice if there were issues).

Check for any custom/hook scripts. If you can duplicate the issue, try clearing out those custom hooks and see if that makes the issue "go away", eg:
/usr/local/directadmin/scripts/custom/*
/usr/local/directadmin/plugins/*/hooks/*

If anyone else is noticing the issues, please let us know.. this is the only report I'm aware of.
 
I ran directadmin with b23 now, and got the following output.

Successful delete/api result:

Code:
auth.authenticated
User::deny_override:/CMD_API_SELECT_USERS:  call_level=2, depth1: aborting due to do depth
User::deny_override:/CMD_DOMAIN:  call_level=2, depth1: aborting due to do depth
User::deny_override:/CMD_DOMAIN:  call_level=1, depth2: aborting due to do depth
Send::snd: adding 9 bytes == 9
Send::snd: adding 6 bytes == 15
Send::snd: adding 2 bytes == 17
Send::snd: adding 28 bytes == 45
Send::snd: adding 23 bytes == 68
Send::snd: adding 17 bytes == 85
Send::snd: adding 10 bytes == 95
Send::snd: adding 2 bytes == 97
Send::snd: adding 101 bytes == 198
Send::snd: adding 19 bytes == 217
Send::snd: adding 14 bytes == 231
Send::snd: adding 10 bytes == 241
Send::snd: adding 4 bytes == 245
IP::removeFromIP(<redacted-ip>, skip_if_owned=0)
Send::snd: adding 7 bytes == 252
Send::snd: adding 6 bytes == 258
Send::snd: adding 15 bytes == 273
Send::snd: adding 9 bytes == 282
Send::snd: adding 444 bytes == 726
Send::~Send: Sent: 726 bytes
Send::~Send: data actually delivered: 726 bytes
sys::remove_tracked_temporary_files: removed temporary file './data/users/<redacted-user>/user.action.lock'

And a successful delete, but with empty API results:

Code:
auth.authenticated
User::deny_override:/CMD_API_SELECT_USERS:  call_level=2, depth1: aborting due to do depth
User::deny_override:/CMD_DOMAIN:  call_level=2, depth1: aborting due to do depth
User::deny_override:/CMD_DOMAIN:  call_level=1, depth2: aborting due to do depth
Send::snd: adding 9 bytes == 9
Send::snd: adding 6 bytes == 15
Send::snd: adding 2 bytes == 17
Send::snd: adding 28 bytes == 45
Send::snd: adding 23 bytes == 68
Send::snd: adding 17 bytes == 85
Send::snd: adding 10 bytes == 95
Send::snd: adding 2 bytes == 97
Send::snd: adding 101 bytes == 198
Send::snd: adding 19 bytes == 217
Send::snd: adding 14 bytes == 231
Send::snd: adding 10 bytes == 241
Send::snd: adding 4 bytes == 245
IP::removeFromIP(<redacted-ip>, skip_if_owned=0)
PIPE HAS BROKEN
Send::~Send: Sent: 726 bytes
Send::~Send: data actually delivered: 245 bytes
Send::~Send: attempted to send 726 bytes, but only 245 were delivered
sys::remove_tracked_temporary_files: removed temporary file './data/users/<redacted-user>/user.action.lock'

The PIPE HAS BROKEN surely doesn't look good. The question is what would cause it though. I noticed that the deletion during the empty result took slightly longer to return.

I have two custom scripts that would run as part of the deletion:

Code:
/usr/local/directadmin/scripts/custom/dns_delete_post.sh -> dns_post
/usr/local/directadmin/scripts/custom/user_destroy_post.sh

The dns_post script is a very fast script that just does some file manipulation to maintain a list of domains on the server. The user_destroy_post.sh is also mostly file manipulations, but it also does a php restart (all installed versions), which may or may not be as quick.

Edit: About the size of the account, it's a tiny little test account with around 100MB of data and seems to be deleted in the foreground. I tried running the deletion with b2000 now as well, and noticed that the output now is slightly different from my original post above, e.g. the PIPE HAS BROKEN message is now also present there.

Success/normal result (runtime ~2 seconds):

Code:
/CMD_API_SELECT_USERS
 0: Accept-Encoding: gzip
 1: Accept: */*
 2: Authorization: Basic <redacted>
 3: Content-Length: 45
 4: Content-Type: application/x-www-form-urlencoded
 5: Da-Ipc-Signature: <redacted>
 6: Da-Licc-Nresellers: -1
 7: Da-Licc-Nusers: -1
 8: Da-Licc-Vdomains: -1
 9: Host: <redacted-host>:2222
10: Https: //<redacted-host>:2222
11: User-Agent: HTTPSocket/3.0.1
12: X-Da-Remote-Ip: <redacted-ip>
13: X-Forwarded-For: <redacted-ip>
Post string: confirmed=Confirm&delete=yes&select0=<redacted-user>
auth.authenticated
User::deny_override:/CMD_API_SELECT_USERS:  call_level=2, depth1: aborting due to do depth
User::deny_override:/CMD_DOMAIN:  call_level=2, depth1: aborting due to do depth
User::deny_override:/CMD_DOMAIN:  call_level=1, depth2: aborting due to do depth
Plugin::addHooks: start
Plugin::addHooks: end
Command::doCommand(/CMD_API_SELECT_USERS)
Database::set_mysqld_ver: got connection version: 10.4.22-MariaDB
Database::set_mysqld_ver: found vesion 10.4.22 mariadb=1
MySQL::getNumUsers:<redacted-user>: Got 1 DB Users
Command::delete_in_background: 1 accounts to be deleted in foreground: 101 <= 10240 AND db_user_count 1 < 500
Reseller::deleteUsers: Deleting account '<redacted-user>' ...
Tally::get_bandwidth_breakdown(ConfigFile &data, int cache=1, int year=0, int month=0): file=./data/users/<redacted-user>/bandwidth.tally.cache
IP::remove_list_from_domain_ips: should_add_domain_to_domainips=0
Ssl::dovecot_sni_reload: reloading dovecot
IP::add_list_to_helo_data: should_add_domain_to_domainips=0
Ftp::removeVirtualHost()
IP::removeFromIP(<redacted-ip>, skip_if_owned=0)
Database::set_mysqld_ver: got connection version: 10.4.22-MariaDB
Database::set_mysqld_ver: found vesion 10.4.22 mariadb=1
killUserProcess: non-zero response from killall process for '<redacted-user>' with exit code 1:
User::destroy: unlock_actions for <redacted-user>
User::destroy:<redacted-user>: DONE
User <redacted-user> removed by admin

Dynamic(api=1, error=0):
    text='Users deleted'
    result='User <redacted-user> Removed<br>
User removed from SSH<br>
<redacted-domain>'s config files have been removed<br>
<br>
Users's domains directory removed.<br>
<br>
Unix User removed from the server<br>
User's config files deleted<br>
User's data directory removed.<br>
Removed user from admin's list<br>
<br>
<br>
'
Command::doCommand(/CMD_API_SELECT_USERS) : finished
Command::run: finished /CMD_API_SELECT_USERS
sys::remove_tracked_temporary_files: removed temporary file './data/users/<redacted-user>/user.action.lock'

Success/empty result (runtime ~5 seconds):

Code:
/CMD_API_SELECT_USERS
 0: Accept-Encoding: gzip
 1: Accept: */*
 2: Authorization: Basic <redacted>
 3: Content-Length: 45
 4: Content-Type: application/x-www-form-urlencoded
 5: Da-Ipc-Signature: <redacted>
 6: Da-Licc-Nresellers: -1
 7: Da-Licc-Nusers: -1
 8: Da-Licc-Vdomains: -1
 9: Host: <redacted-host>:2222
10: Https: //<redacted-host>:2222
11: User-Agent: HTTPSocket/3.0.1
12: X-Da-Remote-Ip: <redacted-ip>
13: X-Forwarded-For: <redacted-ip>
Post string: confirmed=Confirm&delete=yes&select0=<redacted-user>
auth.authenticated
User::deny_override:/CMD_API_SELECT_USERS:  call_level=2, depth1: aborting due to do depth
User::deny_override:/CMD_DOMAIN:  call_level=2, depth1: aborting due to do depth
User::deny_override:/CMD_DOMAIN:  call_level=1, depth2: aborting due to do depth
Plugin::addHooks: start
Plugin::addHooks: end
Command::doCommand(/CMD_API_SELECT_USERS)
Database::set_mysqld_ver: got connection version: 10.4.22-MariaDB
Database::set_mysqld_ver: found vesion 10.4.22 mariadb=1
MySQL::getNumUsers:<redacted-user>: Got 1 DB Users
Command::delete_in_background: 1 accounts to be deleted in foreground: 101 <= 10240 AND db_user_count 1 < 500
Reseller::deleteUsers: Deleting account '<redacted-user>' ...
Tally::get_bandwidth_breakdown(ConfigFile &data, int cache=1, int year=0, int month=0): file=./data/users/<redacted-user>/bandwidth.tally.cache
IP::remove_list_from_domain_ips: should_add_domain_to_domainips=0
Ssl::dovecot_sni_reload: reloading dovecot
IP::add_list_to_helo_data: should_add_domain_to_domainips=0
Ftp::removeVirtualHost()
IP::removeFromIP(<redacted-ip>, skip_if_owned=0)
Database::set_mysqld_ver: got connection version: 10.4.22-MariaDB
Database::set_mysqld_ver: found vesion 10.4.22 mariadb=1
killUserProcess: non-zero response from killall process for '<redacted-user>' with exit code 1:
User::destroy: unlock_actions for <redacted-user>
User::destroy:<redacted-user>: DONE
User <redacted-user> removed by admin

Dynamic(api=1, error=0):
    text='Users deleted'
    result='User <redacted-user> Removed<br>
User removed from SSH<br>
<redacted-domain>'s config files have been removed<br>
<br>
Users's domains directory removed.<br>
<br>
Unix User removed from the server<br>
User's config files deleted<br>
User's data directory removed.<br>
Removed user from admin's list<br>
<br>
<br>
'
PIPE HAS BROKEN
Command::doCommand(/CMD_API_SELECT_USERS) : finished
Command::run: finished /CMD_API_SELECT_USERS
sys::remove_tracked_temporary_files: removed temporary file './data/users/<redacted-user>/user.action.lock'
 
Last edited:
The PIPE HAS BROKEN is on the right track for tracing it.

Looking at the code, that will pop up if either:
  1. Tthe "write" call to the raw socket returns an error. For that case, there should be something in /var/log/directadmin/error.log starting with "Socket write error" providing more info (not sure how useful it will be, but very much related)
  2. or an error with the Send:sendFile call, which is direct file to socket.. not related to the "Dyanmic" output call we're seeing.
So.. there should be something in your error.log relating to #1.

=========

Another thing to check would be to debug again, but level 148 which is for the Sockets class. It would give the same general info about how many bytes were sent per chunk, but would also include the first 10 bytes of output for that chunk, so we can see if perhaps something else was sent first and closed the pipe... or perhaps something else unknown. You'd be looking for debug output that looks like this:
Code:
Sockets::wrt:'%s...': Sending size=%zu

=========
If... the "Go" wrapper is prematurely closing the pipe to "c" (c shows the broken pipe error), then that might be in the Go output log in:
Code:
journalctl -u directadmin
 
I think we're getting somewhere now. I tried again and again, but it wouldn't reproduce, so I added a sleep 5 in my user_destroy_post.sh script to try and provoke the problem, and sure enough, I can now consistently trigger the problem over and over. It seems to be related to some timeout of some kind, somewhere?

Here's the last part of the output from b148 with a normal API result. Everything above is identical:

Code:
Dynamic(api=1, error=0):
    text='Users deleted'
    result='User <redacted-user> Removed<br>
User removed from SSH<br>
<redacted-domain>'s config files have been removed<br>
<br>
Users's domains directory removed.<br>
<br>
Unix User removed from the server<br>
User's config files deleted<br>
User's data directory removed.<br>
Removed user from admin's list<br>
<br>
<br>
'
Sockets::wrt:'error=0...': Sending size=7
Sockets::wrt:'&text=...': Sending size=6
Sockets::wrt:'Users%20de...': Sending size=15
Sockets::wrt:'&details=...': Sending size=9
Sockets::wrt:'User%20uni...': Sending size=444
File ./data/users/admin/users.list has been written to after this process read it.  Not going to overwrite it. This read timestamp=1645705356, before-write timestamp=1645705357
sys::remove_tracked_temporary_files: removed temporary file './data/users/<redacted-user>/user.action.lock'

And this is with empty API result:

Code:
Dynamic(api=1, error=0):
    text='Users deleted'
    result='User <redacted-user> Removed<br>
User removed from SSH<br>
<redacted-domain>'s config files have been removed<br>
<br>
Users's domains directory removed.<br>
<br>
Unix User removed from the server<br>
User's config files deleted<br>
User's data directory removed.<br>
Removed user from admin's list<br>
<br>
<br>
'
Sockets::wrt:'error=0...': Sending size=7
PIPE HAS BROKEN
File ./data/users/admin/users.list has been written to after this process read it.  Not going to overwrite it. This read timestamp=1645707508, before-write timestamp=1645707513
sys::remove_tracked_temporary_files: removed temporary file './data/users/<redacted-user>/user.action.lock'

And this is from error.log for normal API results:

Code:
2022:02:24-13:22:34: db_user_delete: error deleting <redacted-user>: 2022/02/24 13:22:34 fatal executing cli command     error=unrecognized target
2022:02:24-13:22:34: db_domain_delete: <redacted-domain>: 2022/02/24 13:22:34 fatal executing cli command     error=unrecognized target
2022:02:24-13:22:36: ListFile::writeFile(./data/users/admin/users.list) : Timestamp from when it was read is different, overwriting anyway.  This read timestamp=1645623073, before-write timestamp=1645705356
2022:02:24-13:22:37: File ./data/users/admin/users.list has been written to after this process read it.  Not going to overwrite it. This read timestamp=1645705356, before-write timestamp=1645705357
2022:02:24-13:22:37: sys::remove_tracked_temporary_files: removed temporary file './data/users/<redacted-user>/user.action.lock'

And empty API result:

Code:
2022:02:24-13:58:25: db_user_delete: error deleting <redacted-user>: 2022/02/24 13:58:25 fatal executing cli command     error=unrecognized target
2022:02:24-13:58:25: db_domain_delete: <redacted-domain>: 2022/02/24 13:58:25 fatal executing cli command     error=unrecognized target
2022:02:24-13:58:28: ListFile::writeFile(./data/users/admin/users.list) : Timestamp from when it was read is different, overwriting anyway.  This read timestamp=1645707493, before-write timestamp=1645707508
2022:02:24-13:58:33: Socket write error: fd is connected to a pipe or socket whose reading end is closed.  When this  happens the writing process will also receive a SIG_PIPE signal.  (Thus, the write return value is seen only if  the program catches, blocks or ignores this signal.)
2022:02:24-13:58:33: File ./data/users/admin/users.list has been written to after this process read it.  Not going to overwrite it. This read timestamp=1645707508, before-write timestamp=1645707513
2022:02:24-13:58:33: sys::remove_tracked_temporary_files: removed temporary file './data/users/<redacted-user>/user.action.lock'

Journalctl never had any entries.

I suspect that you'd be able to reproduce this locally now as well, considering the sleep 5 made the error consistent?
 
Back
Top